Hello, We are testing IPv6 calls and have run into a problem. I'll describe now. Any ideas for a solution would be appreciated.
The environment is as such: - one machine has an All-in-one install (with a redeployed sprout-base package). this is configured for IPv6 - two other machines each are running PJSUA sip client and, here, are trying to call each other through the proxy on the clearwater machine. I've attached a log from sprout, starting from just before the registration of the two endpoints. My problem is that the logging doesn't really explain why its not forwarding the message. I've done packet captures on all machines and it seems to me that sprout is the last stop of the incoming invite, and no outgoing invite exists on the wire. Please and thank you, Marco.
tail -f /var/log/sprout/*current.txt ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:05:46.186 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:05:56.251 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:06.392 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:16.351 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:26.458 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:36.611 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:46.549 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:06:56.761 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:07:06.690 UTC 200 GET /ping 0.000000 seconds 10-02-2016 21:07:16.742 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/log_current.txt <== 10-02-2016 04:03:40.736 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 10-02-2016 04:08:28.703 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob CONTACT_URI=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob EXPIRES=300 10-02-2016 04:08:35.771 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 10-02-2016 04:13:30.811 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 10-02-2016 04:14:24.280 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob CONTACT_URI=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob EXPIRES=300 10-02-2016 04:15:09.524 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 10-02-2016 04:19:19.330 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob CONTACT_URI=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob EXPIRES=300 10-02-2016 04:20:04.583 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 10-02-2016 04:24:14.374 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob CONTACT_URI=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob EXPIRES=300 10-02-2016 04:24:59.613 UTC Registration: USER_URI=sip:[email protected] BINDING_ID=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob CONTACT_URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob EXPIRES=300 ==> /var/log/sprout/sprout_current.txt <== --end msg-- 10-02-2016 21:07:16.701 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:07:16.701 UTC Debug pjsip: tdta0x7f07b000 Destroying txdata Response msg 200/OPTIONS/cseq=1856 (tdta0x7f07b0009fd0) 10-02-2016 21:07:16.701 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b5058 10-02-2016 21:07:16.701 UTC Debug thread_dispatcher.cpp:199: Request latency = 290us 10-02-2016 21:07:16.742 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:07:16.742 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) 10-02-2016 21:07:17.701 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:07:17.701 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b27b8 has been destroyed 10-02-2016 21:07:17.701 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:07:20.684 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=14995 (rdata0x7f07b80f35e0) 10-02-2016 21:07:20.684 UTC Verbose common_sip_processing.cpp:120: RX 909 bytes Request msg REGISTER/cseq=14995 (rdata0x7f07b80f35e0) from TCP 2400:6180:0:d0::18b:3001:38920: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:38920;rport;branch=z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1 Path: <sip:jOkcJw+mvT@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP [2400:6180:0:d0::160:c001]:5070;rport=5070;received=2400:6180:0:d0::160:c001;branch=z9hG4bKPjVZWvSTGX0sLQG9ITOrWb5ZOOSbaHLRvD Max-Forwards: 70 From: <sip:[email protected]>;tag=qcXJhCkJRbQCI9LAn6Dn2GYlCnKaH-vr To: <sip:[email protected]> Call-ID: bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg CSeq: 14995 REGISTER User-Agent: PJSUA v2.4.5 Linux-3.13.0.71/x86_64/glibc-2.19 Contact: <sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS P-Visited-Network-ID: example.com Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 10-02-2016 21:07:20.684 UTC Debug pjutils.cpp:1648: Logging SAS Call-ID marker, Call-ID bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg 10-02-2016 21:07:20.684 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b80b5838 for worker threads 10-02-2016 21:07:20.684 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b80b5838 10-02-2016 21:07:20.684 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=14995 (rdata0x7f07b80b5838) 10-02-2016 21:07:20.685 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:20.685 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:20.685 UTC Debug authentication.cpp:673: Authentication module invoked 10-02-2016 21:07:20.685 UTC Debug authentication.cpp:687: Request needs authentication 10-02-2016 21:07:20.685 UTC Debug acr.cpp:49: Created ACR (0x7f07b80da9a0) 10-02-2016 21:07:20.685 UTC Debug authentication.cpp:889: No authentication information in request or stale nonce, so reject with challenge 10-02-2016 21:07:20.685 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=14995 (tdta0x7f07b811c5d0) created 10-02-2016 21:07:20.685 UTC Debug pjutils.cpp:423: Private identity defaulted from public identity = [email protected] 10-02-2016 21:07:20.686 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07b811d5e0 10-02-2016 21:07:20.687 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host [2400:6180:0:d0::18b:3001], port 8888, family 10 10-02-2016 21:07:20.687 UTC Debug baseresolver.cpp:513: Attempt to parse [2400:6180:0:d0::18b:3001] as IP address 10-02-2016 21:07:20.687 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:20.687 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://[2400:6180:0:d0::18b:3001]:8888/impi/6505550098%40example.com/av?impu=sip%3A6505550098%40example.com (trying 2400:6180:0:d0::18b:3001) on new connection 10-02-2016 21:07:20.765 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc={"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"}} 10-02-2016 21:07:20.765 UTC Debug communicationmonitor.cpp:82: Checking communication changes - successful attempts 1, failures 0 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:159: Verifying AV: {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"}} 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:186: Digest specified 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:374: Valid AV - generate challenge 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:383: Create WWW-Authenticate header 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:451: Add Digest information 10-02-2016 21:07:20.765 UTC Debug authentication.cpp:493: Write AV to store 10-02-2016 21:07:20.765 UTC Debug avstore.cpp:72: Set AV for [email protected]\131ff1d565852607 {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1"} 10-02-2016 21:07:20.765 UTC Debug memcachedstore.cpp:542: Writing 141 bytes to table av key [email protected]\131ff1d565852607, CAS = 0, expiry = 40 10-02-2016 21:07:20.765 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\131ff1d565852607 hashes to vbucket 12 via hash 0x1f60a18c 10-02-2016 21:07:20.765 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:20.765 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f07b8169990 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f07b8169a00 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:562: 1 write replicas for key av\\[email protected]\131ff1d565852607 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 12 on replica 0 (connection 0x7f07b8169a00), CAS = 0, expiry = 40 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:816: Attempting to add data for key av\\[email protected]\131ff1d565852607 10-02-2016 21:07:20.766 UTC Debug memcachedstore.cpp:826: Attempting memcached ADD command 10-02-2016 21:07:20.767 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 0 (SUCCESS) SUCCESS 10-02-2016 21:07:20.767 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:20.767 UTC Debug communicationmonitor.cpp:82: Checking communication changes - successful attempts 1, failures 0 10-02-2016 21:07:20.767 UTC Debug authentication.cpp:503: Sending {"impi": "[email protected]", "impu": "sip:[email protected]", "nonce": "131ff1d565852607"} to Chronos to set AV timer 10-02-2016 21:07:20.768 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07b8171b70 10-02-2016 21:07:20.769 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 127.0.0.1, port 7253, family 10 10-02-2016 21:07:20.769 UTC Debug baseresolver.cpp:513: Attempt to parse 127.0.0.1 as IP address 10-02-2016 21:07:20.769 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:20.769 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection 10-02-2016 21:07:20.771 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:20.771 UTC Debug httpconnection.cpp:915: Received header location with value /timers/000718a1800000000040001000104104 10-02-2016 21:07:20.771 UTC Debug httpconnection.cpp:915: Received header content-length with value 0 10-02-2016 21:07:20.771 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:20.771 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc= 10-02-2016 21:07:20.771 UTC Debug communicationmonitor.cpp:82: Checking communication changes - successful attempts 1, failures 0 10-02-2016 21:07:20.771 UTC Debug pjsip: tsx0x7f07b8159 Transaction created for Request msg REGISTER/cseq=14995 (rdata0x7f07b80b5838) 10-02-2016 21:07:20.771 UTC Debug pjsip: tsx0x7f07b8159 Incoming Request msg REGISTER/cseq=14995 (rdata0x7f07b80b5838) in state Null 10-02-2016 21:07:20.771 UTC Debug pjsip: tsx0x7f07b8159 State changed from Null to Trying, event=RX_MSG 10-02-2016 21:07:20.772 UTC Debug pjsip: tsx0x7f07b8159 Sending Response msg 401/REGISTER/cseq=14995 (tdta0x7f07b811c5d0) in state Trying 10-02-2016 21:07:20.772 UTC Verbose common_sip_processing.cpp:136: TX 679 bytes Response msg 401/REGISTER/cseq=14995 (tdta0x7f07b811c5d0) to TCP 2400:6180:0:d0::18b:3001:38920: --start msg-- SIP/2.0 401 Unauthorized Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:38920;rport=38920;received=2400:6180:0:d0::18b:3001;branch=z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1 Via: SIP/2.0/UDP [2400:6180:0:d0::160:c001]:5070;rport=5070;received=2400:6180:0:d0::160:c001;branch=z9hG4bKPjVZWvSTGX0sLQG9ITOrWb5ZOOSbaHLRvD Call-ID: bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg From: <sip:[email protected]>;tag=qcXJhCkJRbQCI9LAn6Dn2GYlCnKaH-vr To: <sip:[email protected]>;tag=z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1 CSeq: 14995 REGISTER WWW-Authenticate: Digest realm="example.com",nonce="131ff1d565852607",opaque="74562d5b3aeb4f90",algorithm=MD5,qop="auth" Content-Length: 0 --end msg-- 10-02-2016 21:07:20.772 UTC Debug pjsip: tsx0x7f07b8159 State changed from Trying to Completed, event=TX_MSG 10-02-2016 21:07:20.772 UTC Debug acr.cpp:83: Sending Null ACR (0x7f07b80da9a0) 10-02-2016 21:07:20.772 UTC Debug acr.cpp:54: Destroyed ACR (0x7f07b80da9a0) 10-02-2016 21:07:20.772 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b5838 10-02-2016 21:07:20.772 UTC Debug thread_dispatcher.cpp:199: Request latency = 87700us 10-02-2016 21:07:20.775 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=14996 (rdata0x7f07b8103bb0) 10-02-2016 21:07:20.775 UTC Verbose common_sip_processing.cpp:120: RX 1226 bytes Request msg REGISTER/cseq=14996 (rdata0x7f07b8103bb0) from TCP 2400:6180:0:d0::18b:3001:33221: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:33221;rport;branch=z9hG4bKPjZqsE4Q3qexAQ9pFtEFYUgj64B0MC3yu0 Path: <sip:jOkcJw+mvT@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP [2400:6180:0:d0::160:c001]:5070;rport=5070;received=2400:6180:0:d0::160:c001;branch=z9hG4bKPjmVym-dqb.PeI6ZXKa6kogLtT7YajvFG3 Max-Forwards: 70 From: <sip:[email protected]>;tag=qcXJhCkJRbQCI9LAn6Dn2GYlCnKaH-vr To: <sip:[email protected]> Call-ID: bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg CSeq: 14996 REGISTER User-Agent: PJSUA v2.4.5 Linux-3.13.0.71/x86_64/glibc-2.19 Contact: <sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Authorization: Digest response="d8e7c37eb388ea8769ef559a2d32b12b", username="[email protected]", realm="example.com", nonce="131ff1d565852607", uri="sip:example.com", algorithm=MD5, cnonce="VYG9iiS2Q4JV1EEUJaoli8X1BBm9FZPx", opaque="74562d5b3aeb4f90", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending P-Visited-Network-ID: example.com Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 10-02-2016 21:07:20.775 UTC Debug pjutils.cpp:1648: Logging SAS Call-ID marker, Call-ID bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg 10-02-2016 21:07:20.776 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b80b67e8 for worker threads 10-02-2016 21:07:20.776 UTC Debug pjsip: tsx0x7f07b8159 Timeout timer event 10-02-2016 21:07:20.776 UTC Debug pjsip: tsx0x7f07b8159 State changed from Completed to Terminated, event=TIMER 10-02-2016 21:07:20.776 UTC Debug pjsip: tsx0x7f07b8159 Timeout timer event 10-02-2016 21:07:20.776 UTC Debug pjsip: tsx0x7f07b8159 State changed from Terminated to Destroyed, event=TIMER 10-02-2016 21:07:20.776 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b80b67e8 10-02-2016 21:07:20.776 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=14996 (rdata0x7f07b80b67e8) 10-02-2016 21:07:20.776 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:20.776 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:20.776 UTC Debug authentication.cpp:673: Authentication module invoked 10-02-2016 21:07:20.776 UTC Debug authentication.cpp:581: Authorization header in request 10-02-2016 21:07:20.776 UTC Debug authentication.cpp:687: Request needs authentication 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\131ff1d565852607 hashes to vbucket 12 via hash 0x1f60a18c 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f07c000b4c0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f07c000b570 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:367: 1 read replicas for key av\\[email protected]\131ff1d565852607 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x7f07c000b570) 10-02-2016 21:07:20.776 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:20.776 UTC Debug pjsip: tdta0x7f07b811 Destroying txdata Response msg 401/REGISTER/cseq=14995 (tdta0x7f07b811c5d0) 10-02-2016 21:07:20.776 UTC Debug pjsip: tsx0x7f07b8159 Transaction destroyed! 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:788: Found record on replica 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:410: Read for av\\[email protected]\131ff1d565852607 on replica 0 returned SUCCESS 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:453: Read 141 bytes from table av key [email protected]\131ff1d565852607, CAS = 1 10-02-2016 21:07:20.777 UTC Debug avstore.cpp:106: Retrieved AV for [email protected]\131ff1d565852607 {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1"} 10-02-2016 21:07:20.777 UTC Debug authentication.cpp:743: Verify authentication information in request 10-02-2016 21:07:20.777 UTC Debug authentication.cpp:159: Verifying AV: {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1"} 10-02-2016 21:07:20.777 UTC Debug authentication.cpp:186: Digest specified 10-02-2016 21:07:20.777 UTC Debug authentication.cpp:311: Found Digest HA1 = ed7e862749772ad47596b5bd3c0f2e43 10-02-2016 21:07:20.777 UTC Debug authentication.cpp:749: Request authenticated successfully 10-02-2016 21:07:20.777 UTC Debug avstore.cpp:72: Set AV for [email protected]\131ff1d565852607 {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1","tombstone":true} 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:542: Writing 158 bytes to table av key [email protected]\131ff1d565852607, CAS = 1, expiry = 40 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\131ff1d565852607 hashes to vbucket 12 via hash 0x1f60a18c 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:562: 1 write replicas for key av\\[email protected]\131ff1d565852607 10-02-2016 21:07:20.777 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 12 on replica 0 (connection 0x7f07c000b570), CAS = 1, expiry = 40 10-02-2016 21:07:20.778 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:20.778 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:20.778 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:20.778 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:20.778 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:20.778 UTC Debug acr.cpp:49: Created ACR (0x7f07c0000c40) 10-02-2016 21:07:20.778 UTC Debug registrar.cpp:541: Process REGISTER for public ID sip:[email protected] 10-02-2016 21:07:20.778 UTC Debug registrar.cpp:549: Report SAS start marker - trail (b7) 10-02-2016 21:07:20.778 UTC Debug hssconnection.cpp:585: Making Homestead request for /impu/sip%3A6505550098%40example.com/reg-data?private_id=6505550098%40example.com 10-02-2016 21:07:20.778 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07c0014b30 10-02-2016 21:07:20.779 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host [2400:6180:0:d0::18b:3001], port 8888, family 10 10-02-2016 21:07:20.779 UTC Debug baseresolver.cpp:513: Attempt to parse [2400:6180:0:d0::18b:3001] as IP address 10-02-2016 21:07:20.779 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:20.779 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://[2400:6180:0:d0::18b:3001]:8888/impu/sip%3A6505550098%40example.com/reg-data?private_id=6505550098%40example.com (trying 2400:6180:0:d0::18b:3001) on new connection 10-02-2016 21:07:20.840 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:20.840 UTC Debug httpconnection.cpp:915: Received header content-length with value 813 10-02-2016 21:07:20.840 UTC Debug httpconnection.cpp:915: Received header content-type with value text/plain 10-02-2016 21:07:20.840 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:20.840 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc=<ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription xsi="http://www.w3.org/2001/XMLSchema-instance"; noNamespaceSchemaLocation="CxDataType.xsd"> <PrivateID>Unspecified</PrivateID> <ServiceProfile> <InitialFilterCriteria> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:mmtel.example.com</ServerName> <DefaultHandling>0</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> <PublicIdentity> <Identity>sip:[email protected]</Identity> </PublicIdentity> </ServiceProfile> </IMSSubscription> </ClearwaterRegData> 10-02-2016 21:07:20.840 UTC Debug hssconnection.cpp:366: Processing Identity node from HSS XML - sip:[email protected] 10-02-2016 21:07:20.840 UTC Debug registrar.cpp:651: REGISTER for public ID sip:[email protected] uses AOR sip:[email protected] 10-02-2016 21:07:20.840 UTC Debug subscriber_data_manager.cpp:366: Get AoR data for sip:[email protected] 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:195: Key reg\\sip:[email protected] hashes to vbucket 0 via hash 0xa5f8800 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:367: 1 read replicas for key reg\\sip:[email protected] 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x7f07c000b570) 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:418: Read for reg\\sip:[email protected] on replica 0 returned NOTFOUND 10-02-2016 21:07:20.840 UTC Debug memcachedstore.cpp:492: At least one replica returned not found, so return NOT_FOUND 10-02-2016 21:07:20.840 UTC Debug subscriber_data_manager.cpp:407: Data store returned not found, so create new record, CAS = 0 10-02-2016 21:07:20.840 UTC Debug registrar.cpp:249: Retrieved AoR data 0x7f07c00307e0 10-02-2016 21:07:20.840 UTC Debug registrar.cpp:342: Binding identifier for contact = sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob 10-02-2016 21:07:20.840 UTC Debug registrar.cpp:369: Path header sip:jOkcJw+mvT@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob 10-02-2016 21:07:20.841 UTC Debug subscriber_data_manager.cpp:196: Set AoR data for sip:[email protected], CAS=0, expiry = 1455138750 10-02-2016 21:07:20.841 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07c0062de0 10-02-2016 21:07:20.842 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 127.0.0.1, port 7253, family 10 10-02-2016 21:07:20.842 UTC Debug baseresolver.cpp:513: Attempt to parse 127.0.0.1 as IP address 10-02-2016 21:07:20.842 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:20.842 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection 10-02-2016 21:07:20.843 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:20.844 UTC Debug httpconnection.cpp:915: Received header location with value /timers/000718b3c00000010040001000104104 10-02-2016 21:07:20.844 UTC Debug httpconnection.cpp:915: Received header content-length with value 0 10-02-2016 21:07:20.844 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:20.844 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc= 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:542: Writing 446 bytes to table reg key sip:[email protected], CAS = 0, expiry = 310 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:195: Key reg\\sip:[email protected] hashes to vbucket 0 via hash 0xa5f8800 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:562: 1 write replicas for key reg\\sip:[email protected] 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 0 on replica 0 (connection 0x7f07c000b570), CAS = 0, expiry = 310 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:816: Attempting to add data for key reg\\sip:[email protected] 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:826: Attempting memcached ADD command 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 0 (SUCCESS) SUCCESS 10-02-2016 21:07:20.844 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:20.844 UTC Debug subscriber_data_manager.cpp:438: Data store set_data returned 1 10-02-2016 21:07:20.844 UTC Debug registrar.cpp:116: Bindings for sip:[email protected] 10-02-2016 21:07:20.844 UTC Debug registrar.cpp:130: sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob URI=sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob expires=1455138740 q=0 from=bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg cseq=14996 timer=000718b3c00000010040001000104104 [email protected] emergency_registration=false 10-02-2016 21:07:20.845 UTC Debug pjsip: endpoint Response msg 200/REGISTER/cseq=14996 (tdta0x7f07c009a760) created 10-02-2016 21:07:20.845 UTC Verbose common_sip_processing.cpp:136: TX 860 bytes Response msg 200/REGISTER/cseq=14996 (tdta0x7f07c009a760) to TCP 2400:6180:0:d0::18b:3001:33221: --start msg-- SIP/2.0 200 OK Service-Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:33221;rport=33221;received=2400:6180:0:d0::18b:3001;branch=z9hG4bKPjZqsE4Q3qexAQ9pFtEFYUgj64B0MC3yu0 Via: SIP/2.0/UDP [2400:6180:0:d0::160:c001]:5070;rport=5070;received=2400:6180:0:d0::160:c001;branch=z9hG4bKPjmVym-dqb.PeI6ZXKa6kogLtT7YajvFG3 Call-ID: bycgxu2h8r0Lt282qrPmn7.zbVUHGWJg From: <sip:[email protected]>;tag=qcXJhCkJRbQCI9LAn6Dn2GYlCnKaH-vr To: <sip:[email protected]>;tag=z9hG4bKPjZqsE4Q3qexAQ9pFtEFYUgj64B0MC3yu0 CSeq: 14996 REGISTER Supported: outbound Contact: <sip:6505550098@[2400:6180:0:d0::160:c001]:5070;ob>;expires=300 Require: outbound Path: <sip:jOkcJw+mvT@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> P-Associated-URI: <sip:[email protected]> Content-Length: 0 --end msg-- 10-02-2016 21:07:20.845 UTC Debug acr.cpp:83: Sending Null ACR (0x7f07c0000c40) 10-02-2016 21:07:20.845 UTC Debug acr.cpp:54: Destroyed ACR (0x7f07c0000c40) 10-02-2016 21:07:20.846 UTC Debug ifchandler.cpp:763: Interpreting orig IFC information 10-02-2016 21:07:20.846 UTC Debug ifchandler.cpp:437: SPT class Method: result false 10-02-2016 21:07:20.846 UTC Debug ifchandler.cpp:541: Add to group 0 val false 10-02-2016 21:07:20.846 UTC Debug ifchandler.cpp:559: Result group 0 val false 10-02-2016 21:07:20.846 UTC Debug ifchandler.cpp:572: iFC does not match 10-02-2016 21:07:20.846 UTC Info registration_utils.cpp:187: Found 0 Application Servers 10-02-2016 21:07:20.846 UTC Debug pjsip: tdta0x7f07c009 Destroying txdata Response msg 200/REGISTER/cseq=14996 (tdta0x7f07c009a760) 10-02-2016 21:07:20.846 UTC Debug registrar.cpp:1036: Report SAS end marker - trail (b7) 10-02-2016 21:07:20.846 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b67e8 10-02-2016 21:07:20.846 UTC Debug thread_dispatcher.cpp:199: Request latency = 70230us 10-02-2016 21:07:24.036 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=39544 (rdata0x7f07b80f35e0) 10-02-2016 21:07:24.036 UTC Verbose common_sip_processing.cpp:120: RX 909 bytes Request msg REGISTER/cseq=39544 (rdata0x7f07b80f35e0) from TCP 2400:6180:0:d0::18b:3001:38920: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:38920;rport;branch=z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ Path: <sip:JWSsk2IumG@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP [2400:6180:0:d0::12b:6001]:5070;rport=5070;received=2400:6180:0:d0::12b:6001;branch=z9hG4bKPjgdYG5cxssPjSsMzhjad7j8ugUXWbKnUX Max-Forwards: 70 From: <sip:[email protected]>;tag=tTGWc.BJFJzyCRIodO6GiWzrEAkAbKqH To: <sip:[email protected]> Call-ID: rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx CSeq: 39544 REGISTER User-Agent: PJSUA v2.4.5 Linux-3.13.0.71/x86_64/glibc-2.19 Contact: <sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS P-Visited-Network-ID: example.com Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 10-02-2016 21:07:24.036 UTC Debug pjutils.cpp:1648: Logging SAS Call-ID marker, Call-ID rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx 10-02-2016 21:07:24.036 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b80b5838 for worker threads 10-02-2016 21:07:24.037 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b80b5838 10-02-2016 21:07:24.037 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=39544 (rdata0x7f07b80b5838) 10-02-2016 21:07:24.037 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:24.037 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:24.037 UTC Debug authentication.cpp:673: Authentication module invoked 10-02-2016 21:07:24.037 UTC Debug authentication.cpp:687: Request needs authentication 10-02-2016 21:07:24.037 UTC Debug acr.cpp:49: Created ACR (0x7f07c80040d0) 10-02-2016 21:07:24.037 UTC Debug authentication.cpp:889: No authentication information in request or stale nonce, so reject with challenge 10-02-2016 21:07:24.037 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=39544 (tdta0x7f07c80137f0) created 10-02-2016 21:07:24.037 UTC Debug pjutils.cpp:423: Private identity defaulted from public identity = [email protected] 10-02-2016 21:07:24.039 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07c8014aa0 10-02-2016 21:07:24.042 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host [2400:6180:0:d0::18b:3001], port 8888, family 10 10-02-2016 21:07:24.042 UTC Debug baseresolver.cpp:513: Attempt to parse [2400:6180:0:d0::18b:3001] as IP address 10-02-2016 21:07:24.042 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:24.042 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://[2400:6180:0:d0::18b:3001]:8888/impi/6505550097%40example.com/av?impu=sip%3A6505550097%40example.com (trying 2400:6180:0:d0::18b:3001) on new connection 10-02-2016 21:07:24.059 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc={"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"}} 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:159: Verifying AV: {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"}} 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:186: Digest specified 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:374: Valid AV - generate challenge 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:383: Create WWW-Authenticate header 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:451: Add Digest information 10-02-2016 21:07:24.059 UTC Debug authentication.cpp:493: Write AV to store 10-02-2016 21:07:24.059 UTC Debug avstore.cpp:72: Set AV for [email protected]\6cb85d3b61725048 {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ"} 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:542: Writing 141 bytes to table av key [email protected]\6cb85d3b61725048, CAS = 0, expiry = 40 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\6cb85d3b61725048 hashes to vbucket 14 via hash 0xe64d760e 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f07c804ca70 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f07c8062270 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:562: 1 write replicas for key av\\[email protected]\6cb85d3b61725048 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 14 on replica 0 (connection 0x7f07c8062270), CAS = 0, expiry = 40 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:816: Attempting to add data for key av\\[email protected]\6cb85d3b61725048 10-02-2016 21:07:24.059 UTC Debug memcachedstore.cpp:826: Attempting memcached ADD command 10-02-2016 21:07:24.060 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 0 (SUCCESS) SUCCESS 10-02-2016 21:07:24.060 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:24.060 UTC Debug authentication.cpp:503: Sending {"impi": "[email protected]", "impu": "sip:[email protected]", "nonce": "6cb85d3b61725048"} to Chronos to set AV timer 10-02-2016 21:07:24.061 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x7f07c806a630 10-02-2016 21:07:24.063 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 127.0.0.1, port 7253, family 10 10-02-2016 21:07:24.063 UTC Debug baseresolver.cpp:513: Attempt to parse 127.0.0.1 as IP address 10-02-2016 21:07:24.063 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:24.063 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection 10-02-2016 21:07:24.065 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:24.065 UTC Debug httpconnection.cpp:915: Received header location with value /timers/00071bd9000000020040001000104104 10-02-2016 21:07:24.065 UTC Debug httpconnection.cpp:915: Received header content-length with value 0 10-02-2016 21:07:24.065 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:24.065 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc= 10-02-2016 21:07:24.065 UTC Debug pjsip: tsx0x7f07c8052 Transaction created for Request msg REGISTER/cseq=39544 (rdata0x7f07b80b5838) 10-02-2016 21:07:24.065 UTC Debug pjsip: tsx0x7f07c8052 Incoming Request msg REGISTER/cseq=39544 (rdata0x7f07b80b5838) in state Null 10-02-2016 21:07:24.065 UTC Debug pjsip: tsx0x7f07c8052 State changed from Null to Trying, event=RX_MSG 10-02-2016 21:07:24.065 UTC Debug pjsip: tsx0x7f07c8052 Sending Response msg 401/REGISTER/cseq=39544 (tdta0x7f07c80137f0) in state Trying 10-02-2016 21:07:24.066 UTC Verbose common_sip_processing.cpp:136: TX 679 bytes Response msg 401/REGISTER/cseq=39544 (tdta0x7f07c80137f0) to TCP 2400:6180:0:d0::18b:3001:38920: --start msg-- SIP/2.0 401 Unauthorized Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:38920;rport=38920;received=2400:6180:0:d0::18b:3001;branch=z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ Via: SIP/2.0/UDP [2400:6180:0:d0::12b:6001]:5070;rport=5070;received=2400:6180:0:d0::12b:6001;branch=z9hG4bKPjgdYG5cxssPjSsMzhjad7j8ugUXWbKnUX Call-ID: rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx From: <sip:[email protected]>;tag=tTGWc.BJFJzyCRIodO6GiWzrEAkAbKqH To: <sip:[email protected]>;tag=z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ CSeq: 39544 REGISTER WWW-Authenticate: Digest realm="example.com",nonce="6cb85d3b61725048",opaque="789163944cf2d5bd",algorithm=MD5,qop="auth" Content-Length: 0 --end msg-- 10-02-2016 21:07:24.066 UTC Debug pjsip: tsx0x7f07c8052 State changed from Trying to Completed, event=TX_MSG 10-02-2016 21:07:24.066 UTC Debug acr.cpp:83: Sending Null ACR (0x7f07c80040d0) 10-02-2016 21:07:24.066 UTC Debug acr.cpp:54: Destroyed ACR (0x7f07c80040d0) 10-02-2016 21:07:24.066 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b5838 10-02-2016 21:07:24.066 UTC Debug thread_dispatcher.cpp:199: Request latency = 29267us 10-02-2016 21:07:24.068 UTC Debug pjsip: tsx0x7f07c8052 Timeout timer event 10-02-2016 21:07:24.068 UTC Debug pjsip: tsx0x7f07c8052 State changed from Completed to Terminated, event=TIMER 10-02-2016 21:07:24.068 UTC Debug pjsip: tsx0x7f07c8052 Timeout timer event 10-02-2016 21:07:24.068 UTC Debug pjsip: tsx0x7f07c8052 State changed from Terminated to Destroyed, event=TIMER 10-02-2016 21:07:24.068 UTC Debug pjsip: tdta0x7f07c801 Destroying txdata Response msg 401/REGISTER/cseq=39544 (tdta0x7f07c80137f0) 10-02-2016 21:07:24.068 UTC Debug pjsip: tsx0x7f07c8052 Transaction destroyed! 10-02-2016 21:07:24.069 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=39545 (rdata0x7f07b80f0790) 10-02-2016 21:07:24.069 UTC Verbose common_sip_processing.cpp:120: RX 1226 bytes Request msg REGISTER/cseq=39545 (rdata0x7f07b80f0790) from TCP 2400:6180:0:d0::18b:3001:52176: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:52176;rport;branch=z9hG4bKPjkCkaKE0ron-ujXbJM-3GxJ9kNmmBWE-a Path: <sip:JWSsk2IumG@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP [2400:6180:0:d0::12b:6001]:5070;rport=5070;received=2400:6180:0:d0::12b:6001;branch=z9hG4bKPj50j2Ay3PdKjSNIc1RcAfmwqOD2ivk.mb Max-Forwards: 70 From: <sip:[email protected]>;tag=tTGWc.BJFJzyCRIodO6GiWzrEAkAbKqH To: <sip:[email protected]> Call-ID: rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx CSeq: 39545 REGISTER User-Agent: PJSUA v2.4.5 Linux-3.13.0.71/x86_64/glibc-2.19 Contact: <sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob> Expires: 300 Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Authorization: Digest response="eb6f9789e1d15fb903e9c0ffe0f837ab", username="[email protected]", realm="example.com", nonce="6cb85d3b61725048", uri="sip:example.com", algorithm=MD5, cnonce="Ra3PDVd4ixYT-q1wBtZnpn8PqEQNh1w9", opaque="789163944cf2d5bd", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending P-Visited-Network-ID: example.com Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 10-02-2016 21:07:24.069 UTC Debug pjutils.cpp:1648: Logging SAS Call-ID marker, Call-ID rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx 10-02-2016 21:07:24.069 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b80b5838 for worker threads 10-02-2016 21:07:24.070 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b80b5838 10-02-2016 21:07:24.070 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=39545 (rdata0x7f07b80b5838) 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:673: Authentication module invoked 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:581: Authorization header in request 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:687: Request needs authentication 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\6cb85d3b61725048 hashes to vbucket 14 via hash 0xe64d760e 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x12307b0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:245: Set up connection 0x1265b40 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:367: 1 read replicas for key av\\[email protected]\6cb85d3b61725048 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x1265b40) 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:788: Found record on replica 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:410: Read for av\\[email protected]\6cb85d3b61725048 on replica 0 returned SUCCESS 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:453: Read 141 bytes from table av key [email protected]\6cb85d3b61725048, CAS = 4 10-02-2016 21:07:24.070 UTC Debug avstore.cpp:106: Retrieved AV for [email protected]\6cb85d3b61725048 {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ"} 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:743: Verify authentication information in request 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:159: Verifying AV: {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ"} 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:186: Digest specified 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:311: Found Digest HA1 = 38a357edc0327687dd326d7416c3de69 10-02-2016 21:07:24.070 UTC Debug authentication.cpp:749: Request authenticated successfully 10-02-2016 21:07:24.070 UTC Debug avstore.cpp:72: Set AV for [email protected]\6cb85d3b61725048 {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ","tombstone":true} 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:542: Writing 158 bytes to table av key [email protected]\6cb85d3b61725048, CAS = 4, expiry = 40 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\6cb85d3b61725048 hashes to vbucket 14 via hash 0xe64d760e 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:562: 1 write replicas for key av\\[email protected]\6cb85d3b61725048 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 14 on replica 0 (connection 0x1265b40), CAS = 4, expiry = 40 10-02-2016 21:07:24.070 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:24.070 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:24.070 UTC Debug acr.cpp:49: Created ACR (0x12455b0) 10-02-2016 21:07:24.070 UTC Debug registrar.cpp:541: Process REGISTER for public ID sip:[email protected] 10-02-2016 21:07:24.070 UTC Debug registrar.cpp:549: Report SAS start marker - trail (b9) 10-02-2016 21:07:24.071 UTC Debug hssconnection.cpp:585: Making Homestead request for /impu/sip%3A6505550097%40example.com/reg-data?private_id=6505550097%40example.com 10-02-2016 21:07:24.071 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x126ece0 10-02-2016 21:07:24.073 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host [2400:6180:0:d0::18b:3001], port 8888, family 10 10-02-2016 21:07:24.073 UTC Debug baseresolver.cpp:513: Attempt to parse [2400:6180:0:d0::18b:3001] as IP address 10-02-2016 21:07:24.073 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:24.073 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://[2400:6180:0:d0::18b:3001]:8888/impu/sip%3A6505550097%40example.com/reg-data?private_id=6505550097%40example.com (trying 2400:6180:0:d0::18b:3001) on new connection 10-02-2016 21:07:24.084 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:24.084 UTC Debug httpconnection.cpp:915: Received header content-length with value 813 10-02-2016 21:07:24.084 UTC Debug httpconnection.cpp:915: Received header content-type with value text/plain 10-02-2016 21:07:24.084 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:24.084 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc=<ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription xsi="http://www.w3.org/2001/XMLSchema-instance"; noNamespaceSchemaLocation="CxDataType.xsd"> <PrivateID>Unspecified</PrivateID> <ServiceProfile> <InitialFilterCriteria> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> <Extension/> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:mmtel.example.com</ServerName> <DefaultHandling>0</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> <PublicIdentity> <Identity>sip:[email protected]</Identity> </PublicIdentity> </ServiceProfile> </IMSSubscription> </ClearwaterRegData> 10-02-2016 21:07:24.085 UTC Debug hssconnection.cpp:366: Processing Identity node from HSS XML - sip:[email protected] 10-02-2016 21:07:24.085 UTC Debug registrar.cpp:651: REGISTER for public ID sip:[email protected] uses AOR sip:[email protected] 10-02-2016 21:07:24.085 UTC Debug subscriber_data_manager.cpp:366: Get AoR data for sip:[email protected] 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:195: Key reg\\sip:[email protected] hashes to vbucket 58 via hash 0x60d79c3a 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:367: 1 read replicas for key reg\\sip:[email protected] 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x1265b40) 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:418: Read for reg\\sip:[email protected] on replica 0 returned NOTFOUND 10-02-2016 21:07:24.085 UTC Debug memcachedstore.cpp:492: At least one replica returned not found, so return NOT_FOUND 10-02-2016 21:07:24.085 UTC Debug subscriber_data_manager.cpp:407: Data store returned not found, so create new record, CAS = 0 10-02-2016 21:07:24.085 UTC Debug registrar.cpp:249: Retrieved AoR data 0x128aa10 10-02-2016 21:07:24.085 UTC Debug registrar.cpp:342: Binding identifier for contact = sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob 10-02-2016 21:07:24.085 UTC Debug registrar.cpp:369: Path header sip:JWSsk2IumG@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob 10-02-2016 21:07:24.085 UTC Debug subscriber_data_manager.cpp:196: Set AoR data for sip:[email protected], CAS=0, expiry = 1455138754 10-02-2016 21:07:24.086 UTC Debug httpconnection.cpp:183: Allocated CURL handle 0x12bcf40 10-02-2016 21:07:24.087 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 127.0.0.1, port 7253, family 10 10-02-2016 21:07:24.087 UTC Debug baseresolver.cpp:513: Attempt to parse 127.0.0.1 as IP address 10-02-2016 21:07:24.087 UTC Debug httpresolver.cpp:79: Target is an IP address 10-02-2016 21:07:24.087 UTC Debug httpconnection.cpp:623: Sending HTTP request : http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection 10-02-2016 21:07:24.088 UTC Debug httpconnection.cpp:915: Received header http/1.1200ok with value 10-02-2016 21:07:24.088 UTC Debug httpconnection.cpp:915: Received header location with value /timers/00071bdec00000030040001000104104 10-02-2016 21:07:24.088 UTC Debug httpconnection.cpp:915: Received header content-length with value 0 10-02-2016 21:07:24.088 UTC Debug httpconnection.cpp:915: Received header with value 10-02-2016 21:07:24.088 UTC Debug httpconnection.cpp:638: Received HTTP response: status=200, doc= 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:542: Writing 446 bytes to table reg key sip:[email protected], CAS = 0, expiry = 310 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:195: Key reg\\sip:[email protected] hashes to vbucket 58 via hash 0x60d79c3a 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:562: 1 write replicas for key reg\\sip:[email protected] 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 58 on replica 0 (connection 0x1265b40), CAS = 0, expiry = 310 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:816: Attempting to add data for key reg\\sip:[email protected] 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:826: Attempting memcached ADD command 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 0 (SUCCESS) SUCCESS 10-02-2016 21:07:24.088 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 10-02-2016 21:07:24.088 UTC Debug subscriber_data_manager.cpp:438: Data store set_data returned 1 10-02-2016 21:07:24.088 UTC Debug registrar.cpp:116: Bindings for sip:[email protected] 10-02-2016 21:07:24.088 UTC Debug registrar.cpp:130: sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob URI=sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob expires=1455138744 q=0 from=rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx cseq=39545 timer=00071bdec00000030040001000104104 [email protected] emergency_registration=false 10-02-2016 21:07:24.088 UTC Debug pjsip: endpoint Response msg 200/REGISTER/cseq=39545 (tdta0x12f4940) created 10-02-2016 21:07:24.088 UTC Verbose common_sip_processing.cpp:136: TX 860 bytes Response msg 200/REGISTER/cseq=39545 (tdta0x12f4940) to TCP 2400:6180:0:d0::18b:3001:52176: --start msg-- SIP/2.0 200 OK Service-Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:52176;rport=52176;received=2400:6180:0:d0::18b:3001;branch=z9hG4bKPjkCkaKE0ron-ujXbJM-3GxJ9kNmmBWE-a Via: SIP/2.0/UDP [2400:6180:0:d0::12b:6001]:5070;rport=5070;received=2400:6180:0:d0::12b:6001;branch=z9hG4bKPj50j2Ay3PdKjSNIc1RcAfmwqOD2ivk.mb Call-ID: rpPSADxNjjEHLOh3WJoNliu-mE8QeGcx From: <sip:[email protected]>;tag=tTGWc.BJFJzyCRIodO6GiWzrEAkAbKqH To: <sip:[email protected]>;tag=z9hG4bKPjkCkaKE0ron-ujXbJM-3GxJ9kNmmBWE-a CSeq: 39545 REGISTER Supported: outbound Contact: <sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob>;expires=300 Require: outbound Path: <sip:JWSsk2IumG@[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr;ob> P-Associated-URI: <sip:[email protected]> Content-Length: 0 --end msg-- 10-02-2016 21:07:24.088 UTC Debug acr.cpp:83: Sending Null ACR (0x12455b0) 10-02-2016 21:07:24.088 UTC Debug acr.cpp:54: Destroyed ACR (0x12455b0) 10-02-2016 21:07:24.088 UTC Debug ifchandler.cpp:763: Interpreting orig IFC information 10-02-2016 21:07:24.088 UTC Debug ifchandler.cpp:437: SPT class Method: result false 10-02-2016 21:07:24.088 UTC Debug ifchandler.cpp:541: Add to group 0 val false 10-02-2016 21:07:24.088 UTC Debug ifchandler.cpp:559: Result group 0 val false 10-02-2016 21:07:24.088 UTC Debug ifchandler.cpp:572: iFC does not match 10-02-2016 21:07:24.088 UTC Info registration_utils.cpp:187: Found 0 Application Servers 10-02-2016 21:07:24.088 UTC Debug pjsip: tdta0x12f4940 Destroying txdata Response msg 200/REGISTER/cseq=39545 (tdta0x12f4940) 10-02-2016 21:07:24.088 UTC Debug registrar.cpp:1036: Report SAS end marker - trail (b9) 10-02-2016 21:07:24.088 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b5838 10-02-2016 21:07:24.088 UTC Debug thread_dispatcher.cpp:199: Request latency = 18847us 10-02-2016 21:07:26.788 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35196, sock=749 10-02-2016 21:07:26.788 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:07:26.789 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1866 (rdata0x7f07b80b5af0) 10-02-2016 21:07:26.789 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1866 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35196: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1866 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1866 Call-ID: poll-sip-1866 CSeq: 1866 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:07:26.789 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:26.789 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:26.789 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:07:26.789 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:07:26.789 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:07:26.789 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1866 (rdata0x7f07b815a818) 10-02-2016 21:07:26.789 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:26.789 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:26.789 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1866 (tdta0x7f074c00df50) created 10-02-2016 21:07:26.789 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1866 (tdta0x7f074c00df50) to TCP 2400:6180:0:d0::18b:3001:35196: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35196;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1866 Call-ID: poll-sip-1866 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1866 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1866 CSeq: 1866 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:07:26.789 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:07:26.789 UTC Debug pjsip: tdta0x7f074c00 Destroying txdata Response msg 200/OPTIONS/cseq=1866 (tdta0x7f074c00df50) 10-02-2016 21:07:26.789 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:07:26.789 UTC Debug thread_dispatcher.cpp:199: Request latency = 304us 10-02-2016 21:07:26.791 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:07:26.791 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:26.791 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:27.790 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:07:27.790 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:07:27.790 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:07:36.968 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35208, sock=749 10-02-2016 21:07:36.968 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:07:36.969 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:07:36.969 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:36.969 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:36.975 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1876 (rdata0x7f07b80b5af0) 10-02-2016 21:07:36.975 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1876 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35208: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1876 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1876 Call-ID: poll-sip-1876 CSeq: 1876 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:07:36.975 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:36.975 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:36.975 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:07:36.975 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:07:36.975 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:07:36.975 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1876 (rdata0x7f07b815a818) 10-02-2016 21:07:36.975 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:36.975 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:36.975 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1876 (tdta0x7f075800df50) created 10-02-2016 21:07:36.975 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1876 (tdta0x7f075800df50) to TCP 2400:6180:0:d0::18b:3001:35208: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35208;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1876 Call-ID: poll-sip-1876 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1876 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1876 CSeq: 1876 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:07:36.975 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:07:36.975 UTC Debug pjsip: tdta0x7f075800 Destroying txdata Response msg 200/OPTIONS/cseq=1876 (tdta0x7f075800df50) 10-02-2016 21:07:36.975 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:07:36.975 UTC Debug thread_dispatcher.cpp:199: Request latency = 587us 10-02-2016 21:07:37.975 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:07:37.975 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:07:37.975 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:07:42.922 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=12984 (rdata0x7f07b809e4b0) 10-02-2016 21:07:42.922 UTC Verbose common_sip_processing.cpp:120: RX 1591 bytes Request msg INVITE/cseq=12984 (rdata0x7f07b809e4b0) from TCP 2400:6180:0:d0::18b:3001:50065: --start msg-- INVITE sip:[email protected] SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001]:50065;rport;branch=z9hG4bKPjcXdmum6JycTAGVJe9RH6b26I3hz3R5LU Record-Route: <sip:[2400:6180:0:d0::18b:3001]:5058;transport=TCP;lr> Record-Route: <sip:JWSsk2IumG@[2400:6180:0:d0::18b:3001]:5060;transport=UDP;lr> Via: SIP/2.0/UDP [2400:6180:0:d0::12b:6001]:5070;rport=5070;received=2400:6180:0:d0::12b:6001;branch=z9hG4bKPjTsG.fg54OPAbuOUZmERX-Di0xs8qkyUk Max-Forwards: 70 From: <sip:[email protected]>;tag=9YeJjsfl3nzIgQd15EJ9RWO1SR7AaEXb To: <sip:[email protected]> Contact: <sip:6505550097@[2400:6180:0:d0::12b:6001]:5070;ob> Call-ID: .bMySS7Bo0w.L2cm0TL140Hbex6OoDxt CSeq: 12984 INVITE Allow: PRACK, INVITE, ACK, BYE, CANCEL, UPDATE, INFO, SUBSCRIBE, NOTIFY, REFER, MESSAGE, OPTIONS Supported: replaces, 100rel, timer, norefersub Session-Expires: 600 Min-SE: 90 User-Agent: PJSUA v2.4.5 Linux-3.13.0.71/x86_64/glibc-2.19 P-Asserted-Identity: <sip:[email protected]> Route: <sip:[2400:6180:0:d0::18b:3001]:5054;transport=TCP;lr;orig> Content-Type: application/sdp Content-Length: 482 v=0 o=- 3664127262 3664127262 IN IP4 128.199.195.208 s=pjmedia b=AS:84 t=0 0 a=X-nat:0 m=audio 4000 RTP/AVP 98 97 99 104 3 0 8 9 96 c=IN IP4 128.199.195.208 b=TIAS:64000 a=rtcp:4001 IN IP4 128.199.195.208 a=sendrecv a=rtpmap:98 speex/16000 a=rtpmap:97 speex/8000 a=rtpmap:99 speex/32000 a=rtpmap:104 iLBC/8000 a=fmtp:104 mode=30 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:9 G722/8000 a=rtpmap:96 telephone-event/8000 a=fmtp:96 0-16 --end msg-- 10-02-2016 21:07:42.923 UTC Debug pjutils.cpp:1648: Logging SAS Call-ID marker, Call-ID .bMySS7Bo0w.L2cm0TL140Hbex6OoDxt 10-02-2016 21:07:42.923 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b80b5838 for worker threads 10-02-2016 21:07:42.923 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b80b5838 10-02-2016 21:07:42.923 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=12984 (rdata0x7f07b80b5838) 10-02-2016 21:07:42.923 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:42.923 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:42.923 UTC Debug authentication.cpp:673: Authentication module invoked 10-02-2016 21:07:42.923 UTC Debug authentication.cpp:683: Request does not need authentication 10-02-2016 21:07:42.923 UTC Debug uri_classifier.cpp:167: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:42.923 UTC Debug uri_classifier.cpp:197: Classified URI as 4 10-02-2016 21:07:42.923 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b80b5838 10-02-2016 21:07:42.923 UTC Debug thread_dispatcher.cpp:199: Request latency = 402us 10-02-2016 21:07:47.032 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35218, sock=749 10-02-2016 21:07:47.032 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:07:47.034 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1886 (rdata0x7f07b80b5af0) 10-02-2016 21:07:47.034 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1886 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35218: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1886 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1886 Call-ID: poll-sip-1886 CSeq: 1886 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:07:47.034 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:47.034 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:47.034 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:07:47.035 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:07:47.035 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:07:47.035 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1886 (rdata0x7f07b815a818) 10-02-2016 21:07:47.035 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:47.035 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:47.035 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1886 (tdta0x7f076000df50) created 10-02-2016 21:07:47.035 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1886 (tdta0x7f076000df50) to TCP 2400:6180:0:d0::18b:3001:35218: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35218;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1886 Call-ID: poll-sip-1886 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1886 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1886 CSeq: 1886 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:07:47.035 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:07:47.035 UTC Debug pjsip: tdta0x7f076000 Destroying txdata Response msg 200/OPTIONS/cseq=1886 (tdta0x7f076000df50) 10-02-2016 21:07:47.035 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:07:47.035 UTC Debug thread_dispatcher.cpp:199: Request latency = 421us 10-02-2016 21:07:47.036 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:07:47.036 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:47.037 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:48.036 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:07:48.036 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:07:48.036 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:07:50.780 UTC Verbose httpstack.cpp:286: Process request for URL /authentication-timeout, args (null) 10-02-2016 21:07:50.780 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\131ff1d565852607 hashes to vbucket 12 via hash 0x1f60a18c 10-02-2016 21:07:50.780 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:50.781 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f077c034400 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:50.781 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f077c034470 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:50.781 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:50.781 UTC Debug memcachedstore.cpp:367: 1 read replicas for key av\\[email protected]\131ff1d565852607 10-02-2016 21:07:50.782 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x7f077c034470) 10-02-2016 21:07:50.782 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:50.782 UTC Debug memcachedstore.cpp:788: Found record on replica 10-02-2016 21:07:50.782 UTC Debug memcachedstore.cpp:410: Read for av\\[email protected]\131ff1d565852607 on replica 0 returned SUCCESS 10-02-2016 21:07:50.782 UTC Debug memcachedstore.cpp:453: Read 158 bytes from table av key [email protected]\131ff1d565852607, CAS = 2 10-02-2016 21:07:50.782 UTC Debug communicationmonitor.cpp:82: Checking communication changes - successful attempts 10, failures 0 10-02-2016 21:07:50.782 UTC Debug avstore.cpp:106: Retrieved AV for [email protected]\131ff1d565852607 {"digest":{"ha1":"ed7e862749772ad47596b5bd3c0f2e43","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjjroq9YI-eUVuYSb0le9cNDFAuRIBJ0c1","tombstone":true} 10-02-2016 21:07:50.782 UTC Debug handlers.cpp:651: Tombstone record indicates Authentication Vector has been used successfully - ignoring timer pop 10-02-2016 21:07:50.782 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /authentication-timeout, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:50.783 UTC 200 POST /authentication-timeout 0.003002 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:54.074 UTC Verbose httpstack.cpp:286: Process request for URL /authentication-timeout, args (null) 10-02-2016 21:07:54.075 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\6cb85d3b61725048 hashes to vbucket 14 via hash 0xe64d760e 10-02-2016 21:07:54.075 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 10-02-2016 21:07:54.075 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f0774023320 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 10-02-2016 21:07:54.076 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f0774023390 to server [2400:6180:0:d0::18b:3001]:11211 10-02-2016 21:07:54.076 UTC Debug memcachedstore.cpp:256: Setting server to IP address 2400:6180:0:d0::18b:3001 port 11211 10-02-2016 21:07:54.077 UTC Debug memcachedstore.cpp:367: 1 read replicas for key av\\[email protected]\6cb85d3b61725048 10-02-2016 21:07:54.077 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x7f0774023390) 10-02-2016 21:07:54.077 UTC Debug memcachedstore.cpp:780: Fetch result 10-02-2016 21:07:54.078 UTC Debug memcachedstore.cpp:788: Found record on replica 10-02-2016 21:07:54.078 UTC Debug memcachedstore.cpp:410: Read for av\\[email protected]\6cb85d3b61725048 on replica 0 returned SUCCESS 10-02-2016 21:07:54.078 UTC Debug memcachedstore.cpp:453: Read 158 bytes from table av key [email protected]\6cb85d3b61725048, CAS = 5 10-02-2016 21:07:54.078 UTC Debug avstore.cpp:106: Retrieved AV for [email protected]\6cb85d3b61725048 {"digest":{"ha1":"38a357edc0327687dd326d7416c3de69","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPjF6CDH5bJ8L0DTuwzm0pjifV3rL3z2eTQ","tombstone":true} 10-02-2016 21:07:54.079 UTC Debug handlers.cpp:651: Tombstone record indicates Authentication Vector has been used successfully - ignoring timer pop 10-02-2016 21:07:54.079 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /authentication-timeout, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:54.079 UTC 200 POST /authentication-timeout 0.004859 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:57.091 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35233, sock=753 10-02-2016 21:07:57.091 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:07:57.101 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1896 (rdata0x7f07b80b5af0) 10-02-2016 21:07:57.101 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1896 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35233: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1896 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1896 Call-ID: poll-sip-1896 CSeq: 1896 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:07:57.101 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:57.101 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:57.101 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:07:57.101 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:07:57.101 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:07:57.101 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1896 (rdata0x7f07b815a818) 10-02-2016 21:07:57.101 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:07:57.101 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:07:57.101 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1896 (tdta0x7f075c00df50) created 10-02-2016 21:07:57.101 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1896 (tdta0x7f075c00df50) to TCP 2400:6180:0:d0::18b:3001:35233: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35233;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1896 Call-ID: poll-sip-1896 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1896 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1896 CSeq: 1896 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:07:57.101 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:07:57.101 UTC Debug pjsip: tdta0x7f075c00 Destroying txdata Response msg 200/OPTIONS/cseq=1896 (tdta0x7f075c00df50) 10-02-2016 21:07:57.101 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:07:57.101 UTC Debug thread_dispatcher.cpp:199: Request latency = 610us 10-02-2016 21:07:57.129 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:07:57.129 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:07:57.129 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:07:58.102 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:07:58.102 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:07:58.102 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:07.055 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35243, sock=753 10-02-2016 21:08:07.055 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:07.068 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1906 (rdata0x7f07b80b5af0) 10-02-2016 21:08:07.069 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1906 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35243: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1906 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1906 Call-ID: poll-sip-1906 CSeq: 1906 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:07.069 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:07.069 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:07.069 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:07.069 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:07.069 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:07.069 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1906 (rdata0x7f07b815a818) 10-02-2016 21:08:07.069 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:07.069 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:07.069 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1906 (tdta0x7f076800df50) created 10-02-2016 21:08:07.069 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1906 (tdta0x7f076800df50) to TCP 2400:6180:0:d0::18b:3001:35243: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35243;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1906 Call-ID: poll-sip-1906 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1906 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1906 CSeq: 1906 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:07.069 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:07.069 UTC Debug pjsip: tdta0x7f076800 Destroying txdata Response msg 200/OPTIONS/cseq=1906 (tdta0x7f076800df50) 10-02-2016 21:08:07.069 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:07.069 UTC Debug thread_dispatcher.cpp:199: Request latency = 345us 10-02-2016 21:08:07.092 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:07.092 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:07.092 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:08.070 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:08.070 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:08.070 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:17.117 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:17.117 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:17.117 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:17.128 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35258, sock=753 10-02-2016 21:08:17.128 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:17.129 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1916 (rdata0x7f07b80b5af0) 10-02-2016 21:08:17.129 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1916 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35258: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1916 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1916 Call-ID: poll-sip-1916 CSeq: 1916 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:17.129 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:17.129 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:17.129 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:17.129 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:17.129 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:17.129 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1916 (rdata0x7f07b815a818) 10-02-2016 21:08:17.129 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:17.129 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:17.129 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1916 (tdta0x7f076400df50) created 10-02-2016 21:08:17.129 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1916 (tdta0x7f076400df50) to TCP 2400:6180:0:d0::18b:3001:35258: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35258;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1916 Call-ID: poll-sip-1916 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1916 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1916 CSeq: 1916 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:17.129 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:17.129 UTC Debug pjsip: tdta0x7f076400 Destroying txdata Response msg 200/OPTIONS/cseq=1916 (tdta0x7f076400df50) 10-02-2016 21:08:17.129 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:17.129 UTC Debug thread_dispatcher.cpp:199: Request latency = 293us 10-02-2016 21:08:18.129 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:18.129 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:18.129 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:27.158 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35265, sock=753 10-02-2016 21:08:27.158 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:27.160 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1926 (rdata0x7f07b80b5af0) 10-02-2016 21:08:27.160 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1926 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35265: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1926 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1926 Call-ID: poll-sip-1926 CSeq: 1926 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:27.160 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:27.160 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:27.160 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:27.160 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:27.160 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:27.160 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1926 (rdata0x7f07b815a818) 10-02-2016 21:08:27.160 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:27.160 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:27.160 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1926 (tdta0x7f076c00df50) created 10-02-2016 21:08:27.160 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1926 (tdta0x7f076c00df50) to TCP 2400:6180:0:d0::18b:3001:35265: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35265;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1926 Call-ID: poll-sip-1926 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1926 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1926 CSeq: 1926 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:27.160 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:27.160 UTC Debug pjsip: tdta0x7f076c00 Destroying txdata Response msg 200/OPTIONS/cseq=1926 (tdta0x7f076c00df50) 10-02-2016 21:08:27.160 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:27.160 UTC Debug thread_dispatcher.cpp:199: Request latency = 354us 10-02-2016 21:08:27.192 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:27.192 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:27.192 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:28.160 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:28.160 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:28.160 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:37.210 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35276, sock=753 10-02-2016 21:08:37.210 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:37.210 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1936 (rdata0x7f07b80b5af0) 10-02-2016 21:08:37.210 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1936 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35276: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1936 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1936 Call-ID: poll-sip-1936 CSeq: 1936 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:37.210 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:37.210 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:37.210 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:37.210 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:37.210 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:37.210 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1936 (rdata0x7f07b815a818) 10-02-2016 21:08:37.210 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:37.210 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:37.210 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1936 (tdta0x7f0778010330) created 10-02-2016 21:08:37.210 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1936 (tdta0x7f0778010330) to TCP 2400:6180:0:d0::18b:3001:35276: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35276;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1936 Call-ID: poll-sip-1936 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1936 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1936 CSeq: 1936 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:37.210 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:37.210 UTC Debug pjsip: tdta0x7f077801 Destroying txdata Response msg 200/OPTIONS/cseq=1936 (tdta0x7f0778010330) 10-02-2016 21:08:37.210 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:37.211 UTC Debug thread_dispatcher.cpp:199: Request latency = 379us 10-02-2016 21:08:37.238 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:37.238 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:37.238 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:38.210 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:38.210 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:38.210 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:47.239 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35287, sock=753 10-02-2016 21:08:47.240 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:47.240 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1946 (rdata0x7f07b80b5af0) 10-02-2016 21:08:47.240 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1946 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35287: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1946 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1946 Call-ID: poll-sip-1946 CSeq: 1946 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:47.240 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:47.240 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:47.240 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:47.240 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:47.240 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:47.240 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1946 (rdata0x7f07b815a818) 10-02-2016 21:08:47.240 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:47.240 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:47.240 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1946 (tdta0x7f07740132b0) created 10-02-2016 21:08:47.240 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1946 (tdta0x7f07740132b0) to TCP 2400:6180:0:d0::18b:3001:35287: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35287;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1946 Call-ID: poll-sip-1946 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1946 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1946 CSeq: 1946 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:47.240 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:47.240 UTC Debug pjsip: tdta0x7f077401 Destroying txdata Response msg 200/OPTIONS/cseq=1946 (tdta0x7f07740132b0) 10-02-2016 21:08:47.240 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:47.240 UTC Debug thread_dispatcher.cpp:199: Request latency = 269us 10-02-2016 21:08:47.274 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:47.274 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:47.274 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:48.240 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:48.241 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:48.241 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 10-02-2016 21:08:57.423 UTC Verbose pjsip: tcplis:5054 TCP listener 2400:6180:0:d0::18b:3001:5054: got incoming TCP connection from [2400:6180:0:d0::18b:3001]:35299, sock=753 10-02-2016 21:08:57.423 UTC Verbose pjsip: tcps0x7f07b80b TCP server transport created 10-02-2016 21:08:57.424 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1956 (rdata0x7f07b80b5af0) 10-02-2016 21:08:57.424 UTC Verbose common_sip_processing.cpp:120: RX 413 bytes Request msg OPTIONS/cseq=1956 (rdata0x7f07b80b5af0) from TCP 2400:6180:0:d0::18b:3001:35299: --start msg-- OPTIONS sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054 SIP/2.0 Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport;branch=z9hG4bK-1956 Max-Forwards: 2 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]:5054> From: poll-sip <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1956 Call-ID: poll-sip-1956 CSeq: 1956 OPTIONS Contact: <sip:[2400:6180:0:d0::18b:3001]> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 10-02-2016 21:08:57.424 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:57.424 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:57.424 UTC Debug common_sip_processing.cpp:212: Skipping SAS logging for OPTIONS request 10-02-2016 21:08:57.424 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f07b815a818 for worker threads 10-02-2016 21:08:57.424 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f07b815a818 10-02-2016 21:08:57.424 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1956 (rdata0x7f07b815a818) 10-02-2016 21:08:57.424 UTC Debug uri_classifier.cpp:167: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 10-02-2016 21:08:57.424 UTC Debug uri_classifier.cpp:197: Classified URI as 3 10-02-2016 21:08:57.424 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=1956 (tdta0x7f077c024390) created 10-02-2016 21:08:57.424 UTC Verbose common_sip_processing.cpp:136: TX 326 bytes Response msg 200/OPTIONS/cseq=1956 (tdta0x7f077c024390) to TCP 2400:6180:0:d0::18b:3001:35299: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP [2400:6180:0:d0::18b:3001];rport=35299;received=2400:6180:0:d0::18b:3001;branch=z9hG4bK-1956 Call-ID: poll-sip-1956 From: "poll-sip" <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=1956 To: <sip:poll-sip@[2400:6180:0:d0::18b:3001]>;tag=z9hG4bK-1956 CSeq: 1956 OPTIONS Content-Length: 0 --end msg-- 10-02-2016 21:08:57.424 UTC Debug common_sip_processing.cpp:254: Skipping SAS logging for OPTIONS response 10-02-2016 21:08:57.424 UTC Debug pjsip: tdta0x7f077c02 Destroying txdata Response msg 200/OPTIONS/cseq=1956 (tdta0x7f077c024390) 10-02-2016 21:08:57.424 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f07b815a818 10-02-2016 21:08:57.424 UTC Debug thread_dispatcher.cpp:199: Request latency = 681us 10-02-2016 21:08:57.466 UTC Verbose httpstack.cpp:286: Process request for URL /ping, args (null) 10-02-2016 21:08:57.466 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) ==> /var/log/sprout/access_current.txt <== 10-02-2016 21:08:57.466 UTC 200 GET /ping 0.000000 seconds ==> /var/log/sprout/sprout_current.txt <== 10-02-2016 21:08:58.424 UTC Verbose pjsip: tcps0x7f07b80b TCP connection closed 10-02-2016 21:08:58.424 UTC Debug connection_tracker.cpp:91: Connection 0x7f07b80b57b8 has been destroyed 10-02-2016 21:08:58.424 UTC Verbose pjsip: tcps0x7f07b80b TCP transport destroyed with reason 70016: End of file (PJ_EEOF) ^C
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
