Glad to hear it worked! -- Rob Day Software Engineer, Project Clearwater
From: atva angel [mailto:[email protected]] Sent: 29 June 2015 17:13 To: Robert Day; Clearwater Mail Subject: Re: [Clearwater] S-CSCF returns 403 Forbidden due to cURL failure with cURL error code 0 Thanks Robert, I got the issue with your suggestion. The authorized format should be privateid@domain. Regards, Tam Vo On Wednesday, June 24, 2015 11:51 PM, Robert Day <[email protected]<mailto:[email protected]>> wrote: Hi Tam Vo, The Authorization header that X-Lite is sending in is: Authorization: Digest username="7107204018", realm="example.com", nonce="7ddf3cfa67ba46bb", uri="sip:example.com", response="612f62e73abddbeec9d82ad5ff7120c7", algorithm=MD5, cnonce="1f0876e3a01bf152f5d20335a797800b", opaque="1d5cd17028c1f33b", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending Note that the “username” field is just “7107204018”, whereas I’d expect [email protected]<mailto:[email protected]> (matching the private identity shown in Ellis) – because this is wrong, Homestead can’t find the subscriber and returns 404, which is why HTTP errors are reported. The fix is to set your ‘Authorization name’ in X-Lite to [email protected]<mailto:[email protected]>. Best, Rob -- Rob Day Software Engineer, Project Clearwater From: [email protected]<mailto:[email protected]> [mailto:[email protected]] On Behalf Of atva angel Sent: 24 June 2015 16:35 To: Clearwater Mail Subject: [Clearwater] S-CSCF returns 403 Forbidden due to cURL failure with cURL error code 0 Hi community, I have clearwater imscore installed manually done with 6 machines. When I register the IMS user from X-lite, S-CSCF returns 403 Forbidden due to cURL failure with cURL error code 0. Could you please help to take a look and share your advice? Thanks. #On the machine runs sprout root@ubun3:~# cat /etc/clearwater/config # Deployment definitions home_domain=example.com bono_hostname=137.116.157.173 sprout_hostname=137.116.157.174 #chronos_hostname=:7253 hs_hostname=137.116.157.176:8888 hs_provisioning_hostname=137.116.157.176:8889 ralf_hostname=137.116.157.177:10888 xdms_hostname=137.116.157.175:7888 # Local IP configuration local_ip=137.116.157.174 public_ip=137.116.157.174 public_hostname=137.116.157.174 # Email server configuration smtp_smarthost=127.0.0.1 smtp_username=username smtp_password=password email_recovery_sender=clearwater@xxxxxxxxxxx # Keys signup_key=secret turn_workaround=secret ellis_api_key=secret ellis_cookie_key=secret # I-CSCF/S-CSCF configuration #icscf=5052 #scscf=5054 #sprout log root@ubun3:/etc/clearwater# root@ubun3:/etc/clearwater# tail -f /var/log/sprout/sprout_current.txt 24-06-2015 12:28:20.936 UTC Debug thread_dispatcher.cpp:176: Worker thread completed processing message 0x7f8db406b688 24-06-2015 12:28:20.936 UTC Debug thread_dispatcher.cpp:182: Request latency = 371us 24-06-2015 12:28:20.936 UTC Debug statistic.cpp:103: Send new value for statistic latency_us, size 5 24-06-2015 12:28:20.936 UTC Debug zmq_lvc.cpp:172: Update to latency_us statistic 24-06-2015 12:28:20.936 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8012ff0 24-06-2015 12:28:20.942 UTC Verbose httpstack.cpp:281: Process request for URL /ping, args (null) 24-06-2015 12:28:20.942 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) 24-06-2015 12:28:21.939 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed 24-06-2015 12:28:21.939 UTC Debug connection_tracker.cpp:91: Connection 0x7f8db4172e38 has been destroyed 24-06-2015 12:28:21.939 UTC Verbose pjsip: tcps0x7f8db417 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 24-06-2015 12:28:30.960 UTC Verbose pjsip: tcplis:5054 TCP listener 137.116.157.174:5054: got incoming TCP connection from 137.116.157.174:35144, sock=374 24-06-2015 12:28:30.960 UTC Verbose pjsip: tcps0x7f8db417 TCP server transport created 24-06-2015 12:28:30.961 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=3190 (rdata0x7f8db4173170) 24-06-2015 12:28:30.961 UTC Verbose common_sip_processing.cpp:120: RX 358 bytes Request msg OPTIONS/cseq=3190 (rdata0x7f8db4173170) from TCP 137.116.157.174:35144: --start msg-- OPTIONS sip:[email protected]:5054 SIP/2.0 Via: SIP/2.0/TCP 137.116.157.174;rport;branch=z9hG4bK-3190 Max-Forwards: 2 To: <sip:[email protected]:5054> From: poll-sip <sip:[email protected]>;tag=3190 Call-ID: poll-sip-3190 CSeq: 3190 OPTIONS Contact: <sip:137.116.157.174> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to incoming_requests statistic 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de802a270 24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:236: Queuing cloned received message 0x7f8db406b688 for worker threads 24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for statistic queue_size, size 5 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to queue_size statistic 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de80335b0 24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f8db406b688 24-06-2015 12:28:30.961 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=3190 (rdata0x7f8db406b688) 24-06-2015 12:28:30.961 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0) created 24-06-2015 12:28:30.961 UTC Verbose common_sip_processing.cpp:136: TX 284 bytes Response msg 200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0) to TCP 137.116.157.174:35144: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 137.116.157.174;rport=35144;received=137.116.157.174;branch=z9hG4bK-3190 Call-ID: poll-sip-3190 From: "poll-sip" <sip:[email protected]>;tag=3190 To: <sip:[email protected]>;tag=z9hG4bK-3190 CSeq: 3190 OPTIONS Content-Length: 0 --end msg-- 24-06-2015 12:28:30.961 UTC Debug pjsip: tdta0x7f8db403 Destroying txdata Response msg 200/OPTIONS/cseq=3190 (tdta0x7f8db403eaa0) 24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:176: Worker thread completed processing message 0x7f8db406b688 24-06-2015 12:28:30.961 UTC Debug thread_dispatcher.cpp:182: Request latency = 296us 24-06-2015 12:28:30.961 UTC Debug statistic.cpp:103: Send new value for statistic latency_us, size 5 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:172: Update to latency_us statistic 24-06-2015 12:28:30.961 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8012ff0 24-06-2015 12:28:30.964 UTC Verbose httpstack.cpp:281: Process request for URL /ping, args (null) 24-06-2015 12:28:30.964 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) 24-06-2015 12:28:31.965 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed 24-06-2015 12:28:31.966 UTC Debug connection_tracker.cpp:91: Connection 0x7f8db4172e38 has been destroyed 24-06-2015 12:28:31.966 UTC Verbose pjsip: tcps0x7f8db417 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 24-06-2015 12:28:38.286 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=1 (rdata0x7f8db40536b0) 24-06-2015 12:28:38.286 UTC Verbose common_sip_processing.cpp:120: RX 875 bytes Request msg REGISTER/cseq=1 (rdata0x7f8db40536b0) from TCP 137.116.157.173:41219: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP 137.116.157.173:41219;rport;branch=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j Path: <sip:[email protected]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP 137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-886a6262b8691d67-1---d8754z- Max-Forwards: 70 Contact: <sip:[email protected]:3214;rinstance=298bd1a969f6f2b8> To: "7107204018" <sip:[email protected]> From: "7107204018" <sip:[email protected]>;tag=3f31ad3b Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. CSeq: 1 REGISTER Expires: 3600 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: X-Lite release 1104o stamp 56125 P-Visited-Network-ID: example.com Session-Expires: 600 Route: <sip:137.116.157.174:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 24-06-2015 12:28:38.286 UTC Debug statistic.cpp:103: Send new value for statistic incoming_requests, size 1 24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:172: Update to incoming_requests statistic 24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de802a270 24-06-2015 12:28:38.287 UTC Debug thread_dispatcher.cpp:236: Queuing cloned received message 0x7f8db406a678 for worker threads 24-06-2015 12:28:38.287 UTC Debug statistic.cpp:103: Send new value for statistic queue_size, size 5 24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:172: Update to queue_size statistic 24-06-2015 12:28:38.287 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de80335b0 24-06-2015 12:28:38.287 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f8db406a678 24-06-2015 12:28:38.288 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=1 (rdata0x7f8db406a678) 24-06-2015 12:28:38.288 UTC Debug acr.cpp:1743: Create RalfACR for node type S-CSCF with role Originating 24-06-2015 12:28:38.288 UTC Debug acr.cpp:49: Created ACR (0x7f8db00cd7d0) 24-06-2015 12:28:38.288 UTC Debug acr.cpp:171: Created S-CSCF Ralf ACR 24-06-2015 12:28:38.288 UTC Debug acr.cpp:210: Set record type for P/S-CSCF 24-06-2015 12:28:38.288 UTC Debug acr.cpp:218: Non-dialog message => EVENT_RECORD 24-06-2015 12:28:38.288 UTC Debug acr.cpp:1471: Stored 0 subscription identifiers 24-06-2015 12:28:38.288 UTC Debug authentication.cpp:730: No authentication information in request or stale nonce, so reject with challenge 24-06-2015 12:28:38.288 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=1 (tdta0x7f8db00af940) created 24-06-2015 12:28:38.288 UTC Debug pjutils.cpp:470: Private identity defaulted from public identity = [email protected]<mailto:[email protected]> 24-06-2015 12:28:38.289 UTC Debug httpconnection.cpp:191: Allocated CURL handle 0x7f8db0156680 24-06-2015 12:28:38.289 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 137.116.157.176, port 8888, family 2 24-06-2015 12:28:38.289 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.176 as IP address 24-06-2015 12:28:38.289 UTC Debug httpresolver.cpp:79: Target is an IP address 24-06-2015 12:28:38.289 UTC Debug httpconnection.cpp:614: Sending HTTP request : http://137.116.157.176:8888/impi/7107204018%40example.com/av?impu=sip%3A7107204018%40example.com (trying 137.116.157.176) on new connection 24-06-2015 12:28:38.299 UTC Debug httpconnection.cpp:629: Received HTTP response: status=200, doc={"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"}} 24-06-2015 12:28:38.299 UTC Debug statistic.cpp:103: Send new value for statistic connected_homesteads, size 2 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to connected_homesteads statistic 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8009cb0 24-06-2015 12:28:38.300 UTC Debug statistic.cpp:103: Send new value for statistic hss_latency_us, size 5 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to hss_latency_us statistic 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8017980 24-06-2015 12:28:38.300 UTC Debug statistic.cpp:103: Send new value for statistic hss_digest_latency_us, size 5 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:172: Update to hss_digest_latency_us statistic 24-06-2015 12:28:38.300 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de801c320 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:124: Verifying AV: {"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"}} 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:151: Digest specified 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:334: Valid AV - generate challenge 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:340: Create WWW-Authenticate header 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:402: Add Digest information 24-06-2015 12:28:38.301 UTC Debug authentication.cpp:444: Write AV to store 24-06-2015 12:28:38.301 UTC Debug avstore.cpp:72: Set AV for [email protected]\7ddf3cfa67ba46bb<mailto:[email protected]\7ddf3cfa67ba46bb> {"digest":{"ha1":"dfa242abefea9c2259824c64f7003c31","realm":"example.com","qop":"auth"},"branch":"z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j"} 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:542: Writing 141 bytes to table av key [email protected]\7ddf3cfa67ba46bb<mailto:[email protected]\7ddf3cfa67ba46bb>, CAS = 0, expiry = 40 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:195: Key av\\[email protected]\7ddf3cfa67ba46bb hashes to vbucket 126 via hash 0x3dff5efe 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f8db00a7cc0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f8db00a7d30 to server 137.116.157.174:11211 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:256: Setting server to IP address 137.116.157.174 port 11211 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:562: 1 write replicas for key av\\[email protected]\7ddf3cfa67ba46bb 24-06-2015 12:28:38.301 UTC Debug memcachedstore.cpp:616: Attempt conditional write to vbucket 126 on replica 0 (connection 0x7f8db00a7d30), CAS = 0, expiry = 40 24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:816: Attempting to add data for key av\\[email protected]\7ddf3cfa67ba46bb 24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:826: Attempting memcached ADD command 24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 0 (SUCCESS) SUCCESS 24-06-2015 12:28:38.302 UTC Debug memcachedstore.cpp:657: Conditional write succeeded to replica 0 24-06-2015 12:28:38.302 UTC Debug authentication.cpp:454: Sending {"impi": "[email protected]<mailto:[email protected]>", "impu": "sip:[email protected]", "nonce": "7ddf3cfa67ba46bb"} to Chronos to set AV timer 24-06-2015 12:28:38.302 UTC Debug httpconnection.cpp:191: Allocated CURL handle 0x7f8db01a0800 24-06-2015 12:28:38.303 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 127.0.0.1, port 7253, family 2 24-06-2015 12:28:38.303 UTC Debug baseresolver.cpp:503: Attempt to parse 127.0.0.1 as IP address 24-06-2015 12:28:38.303 UTC Debug httpresolver.cpp:79: Target is an IP address 24-06-2015 12:28:38.303 UTC Debug httpconnection.cpp:614: Sending HTTP request : http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection 24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header http/1.1200ok with value 24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header location with value /timers/ffffffffc00000040040001000104104 24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header content-length with value 0 24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:914: Received header with value 24-06-2015 12:28:38.304 UTC Debug httpconnection.cpp:629: Received HTTP response: status=200, doc= 24-06-2015 12:28:38.304 UTC Verbose common_sip_processing.cpp:136: TX 651 bytes Response msg 401/REGISTER/cseq=1 (tdta0x7f8db00af940) to TCP 137.116.157.173:41219: --start msg-- SIP/2.0 401 Unauthorized Via: SIP/2.0/TCP 137.116.157.173:41219;rport=41219;received=137.116.157.173;branch=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j Via: SIP/2.0/UDP 137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-886a6262b8691d67-1---d8754z- Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. From: "7107204018" <sip:[email protected]>;tag=3f31ad3b To: "7107204018" <sip:[email protected]>;tag=z9hG4bKPji-nevKQYcoUiCAkw4-aDvXPa3DWTNc9j CSeq: 1 REGISTER WWW-Authenticate: Digest realm="example.com",nonce="7ddf3cfa67ba46bb",opaque="1d5cd17028c1f33b",algorithm=MD5,qop="auth" Content-Length: 0 --end msg-- 24-06-2015 12:28:38.304 UTC Debug pjsip: tdta0x7f8db00a Destroying txdata Response msg 401/REGISTER/cseq=1 (tdta0x7f8db00af940) 24-06-2015 12:28:38.304 UTC Info acr.cpp:648: No CCF or ECF to send ACR for session ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. to - dropping! 24-06-2015 12:28:38.305 UTC Debug acr.cpp:54: Destroyed ACR (0x7f8db00cd7d0) 24-06-2015 12:28:38.305 UTC Debug thread_dispatcher.cpp:176: Worker thread completed processing message 0x7f8db406a678 24-06-2015 12:28:38.305 UTC Debug thread_dispatcher.cpp:182: Request latency = 17777us 24-06-2015 12:28:38.305 UTC Debug statistic.cpp:103: Send new value for statistic latency_us, size 5 24-06-2015 12:28:38.305 UTC Debug zmq_lvc.cpp:172: Update to latency_us statistic 24-06-2015 12:28:38.305 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8012ff0 24-06-2015 12:28:38.550 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=2 (rdata0x7f8db400aab0) 24-06-2015 12:28:38.550 UTC Verbose common_sip_processing.cpp:120: RX 1180 bytes Request msg REGISTER/cseq=2 (rdata0x7f8db400aab0) from TCP 137.116.157.173:51538: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP 137.116.157.173:51538;rport;branch=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX Path: <sip:[email protected]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP 137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-f5095d7a4d239b01-1---d8754z- Max-Forwards: 70 Contact: <sip:[email protected]:3214;rinstance=298bd1a969f6f2b8> To: "7107204018" <sip:[email protected]> From: "7107204018" <sip:[email protected]>;tag=3f31ad3b Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. CSeq: 2 REGISTER Expires: 3600 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: X-Lite release 1104o stamp 56125 Authorization: Digest username="7107204018", realm="example.com", nonce="7ddf3cfa67ba46bb", uri="sip:example.com", response="612f62e73abddbeec9d82ad5ff7120c7", algorithm=MD5, cnonce="1f0876e3a01bf152f5d20335a797800b", opaque="1d5cd17028c1f33b", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending P-Visited-Network-ID: example.com Session-Expires: 600 Route: <sip:137.116.157.174:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 24-06-2015 12:28:38.550 UTC Debug thread_dispatcher.cpp:236: Queuing cloned received message 0x7f8db406a678 for worker threads 24-06-2015 12:28:38.550 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f8db406a678 24-06-2015 12:28:38.550 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=2 (rdata0x7f8db406a678) 24-06-2015 12:28:38.550 UTC Debug authentication.cpp:544: Authorization header in request 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:195: Key av\\7107204018\7ddf3cfa67ba46bb hashes to vbucket 115 via hash 0xfd57b173 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:236: Set up new view 1 for thread 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:243: Setting up server 0 for connection 0x7f8db80b9150 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 --BINARY-PROTOCOL) 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:245: Set up connection 0x7f8db8007310 to server 137.116.157.174:11211 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:256: Setting server to IP address 137.116.157.174 port 11211 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:367: 1 read replicas for key av\\7107204018\7ddf3cfa67ba46bb 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:402: Attempt to read from replica 0 (connection 0x7f8db8007310) 24-06-2015 12:28:38.551 UTC Debug memcachedstore.cpp:780: Fetch result 24-06-2015 12:28:38.552 UTC Debug memcachedstore.cpp:418: Read for av\\7107204018\7ddf3cfa67ba46bb on replica 0 returned NOTFOUND 24-06-2015 12:28:38.552 UTC Debug memcachedstore.cpp:492: At least one replica returned not found, so return NOT_FOUND 24-06-2015 12:28:38.552 UTC Debug authentication.cpp:597: Verify authentication information in request 24-06-2015 12:28:38.552 UTC Warning authentication.cpp:209: Received an authentication request for 7107204018 with nonce 7ddf3cfa67ba46bb, but no matching AV found 24-06-2015 12:28:38.552 UTC Debug acr.cpp:1743: Create RalfACR for node type S-CSCF with role Originating 24-06-2015 12:28:38.552 UTC Debug acr.cpp:49: Created ACR (0x7f8db8196350) 24-06-2015 12:28:38.552 UTC Debug acr.cpp:171: Created S-CSCF Ralf ACR 24-06-2015 12:28:38.552 UTC Debug acr.cpp:210: Set record type for P/S-CSCF 24-06-2015 12:28:38.552 UTC Debug acr.cpp:218: Non-dialog message => EVENT_RECORD 24-06-2015 12:28:38.552 UTC Debug acr.cpp:1471: Stored 0 subscription identifiers 24-06-2015 12:28:38.552 UTC Debug authentication.cpp:730: No authentication information in request or stale nonce, so reject with challenge 24-06-2015 12:28:38.552 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=2 (tdta0x7f8db81966b0) created 24-06-2015 12:28:38.552 UTC Debug pjutils.cpp:463: Private identity from authorization header = 7107204018 24-06-2015 12:28:38.553 UTC Debug httpconnection.cpp:191: Allocated CURL handle 0x7f8db81dc3d0 24-06-2015 12:28:38.554 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 137.116.157.176, port 8888, family 2 24-06-2015 12:28:38.554 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.176 as IP address 24-06-2015 12:28:38.554 UTC Debug httpresolver.cpp:79: Target is an IP address 24-06-2015 12:28:38.554 UTC Debug httpconnection.cpp:614: Sending HTTP request : http://137.116.157.176:8888/impi/7107204018/av?impu=sip%3A7107204018%40example.com (trying 137.116.157.176) on new connection 24-06-2015 12:28:38.558 UTC Debug httpconnection.cpp:629: Received HTTP response: status=404, doc= 24-06-2015 12:28:38.558 UTC Debug statistic.cpp:103: Send new value for statistic connected_homesteads, size 2 24-06-2015 12:28:38.558 UTC Debug zmq_lvc.cpp:172: Update to connected_homesteads statistic 24-06-2015 12:28:38.558 UTC Debug zmq_lvc.cpp:256: Clearing message cache for 0x7f8de8009cb0 24-06-2015 12:28:38.558 UTC Error httpconnection.cpp:748: cURL failure with cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 404 24-06-2015 12:28:38.558 UTC Error hssconnection.cpp:143: Failed to get Authentication Vector for 7107204018 24-06-2015 12:28:38.559 UTC Debug authentication.cpp:474: Failed to get Authentication vector 24-06-2015 12:28:38.559 UTC Verbose common_sip_processing.cpp:136: TX 525 bytes Response msg 403/REGISTER/cseq=2 (tdta0x7f8db81966b0) to TCP 137.116.157.173:51538: --start msg-- SIP/2.0 403 Forbidden Via: SIP/2.0/TCP 137.116.157.173:51538;rport=51538;received=137.116.157.173;branch=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX Via: SIP/2.0/UDP 137.116.157.232:3214;rport=3214;received=137.116.157.232;branch=z9hG4bK-d8754z-f5095d7a4d239b01-1---d8754z- Call-ID: ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. From: "7107204018" <sip:[email protected]>;tag=3f31ad3b To: "7107204018" <sip:[email protected]>;tag=z9hG4bKPjZp.BQJwh-2TUjg.Ynx-Z0vtONh3SnXbX CSeq: 2 REGISTER Content-Length: 0 --end msg-- 24-06-2015 12:28:38.559 UTC Debug pjsip: tdta0x7f8db819 Destroying txdata Response msg 403/REGISTER/cseq=2 (tdta0x7f8db81966b0) 24-06-2015 12:28:38.559 UTC Info acr.cpp:648: No CCF or ECF to send ACR for session ZGRjYmZlZjdiZTNiMzBmODMyYzA2ODdmZWNkZmI2ZDM. to - dropping! 24-06-2015 12:28:38.559 UTC Debug acr.cpp:54: Destroyed ACR (0x7f8db8196350) 24-06-2015 12:28:38.559 UTC Debug thread_dispatcher.cpp:176: Worker thread completed processing message 0x7f8db406a678 24-06-2015 12:28:38.559 UTC Debug thread_dispatcher.cpp:182: Request latency = 9248us 24-06-2015 12:28:38.559 UTC Info load_monitor.cpp:194: Accepted 100.000000% of requests, latency error = -0.966900, overload responses = 0 24-06-2015 12:28:38.560 UTC Status load_monitor.cpp:221: Maximum incoming request rate/second increased to 168.563904 (based on a smoothed mean latency of 3310 and 0 upstream overload responses) 24-06-2015 12:28:40.984 UTC Verbose pjsip: tcplis:5054 TCP listener 137.116.157.174:5054: got incoming TCP connection from 137.116.157.174:35221, sock=437 24-06-2015 12:28:40.985 UTC Verbose pjsip: tcps0x7f8db417 TCP server transport created 24-06-2015 12:28:40.985 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=3200 (rdata0x7f8db4173170) 24-06-2015 12:28:40.985 UTC Verbose common_sip_processing.cpp:120: RX 358 bytes Request msg OPTIONS/cseq=3200 (rdata0x7f8db4173170) from TCP 137.116.157.174:35221: --start msg-- OPTIONS sip:[email protected]:5054 SIP/2.0 Via: SIP/2.0/TCP 137.116.157.174;rport;branch=z9hG4bK-3200 Max-Forwards: 2 To: <sip:[email protected]:5054> From: poll-sip <sip:[email protected]>;tag=3200 Call-ID: poll-sip-3200 CSeq: 3200 OPTIONS Contact: <sip:137.116.157.174> Accept: application/sdp Content-Length: 0 User-Agent: poll-sip --end msg-- 24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:236: Queuing cloned received message 0x7f8db406b688 for worker threads 24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f8db406b688 24-06-2015 12:28:40.985 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=3200 (rdata0x7f8db406b688) 24-06-2015 12:28:40.985 UTC Debug pjsip: endpoint Response msg 200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600) created 24-06-2015 12:28:40.985 UTC Verbose common_sip_processing.cpp:136: TX 284 bytes Response msg 200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600) to TCP 137.116.157.174:35221: --start msg-- SIP/2.0 200 OK Via: SIP/2.0/TCP 137.116.157.174;rport=35221;received=137.116.157.174;branch=z9hG4bK-3200 Call-ID: poll-sip-3200 From: "poll-sip" <sip:[email protected]>;tag=3200 To: <sip:[email protected]>;tag=z9hG4bK-3200 CSeq: 3200 OPTIONS Content-Length: 0 --end msg-- 24-06-2015 12:28:40.985 UTC Debug pjsip: tdta0x7f8dd80d Destroying txdata Response msg 200/OPTIONS/cseq=3200 (tdta0x7f8dd80de600) 24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:176: Worker thread completed processing message 0x7f8db406b688 24-06-2015 12:28:40.985 UTC Debug thread_dispatcher.cpp:182: Request latency = 173us 24-06-2015 12:28:40.991 UTC Verbose httpstack.cpp:281: Process request for URL /ping, args (null) 24-06-2015 12:28:40.991 UTC Verbose httpstack.cpp:69: Sending response 200 to request for URL /ping, args (null) 24-06-2015 12:28:41.988 UTC Verbose pjsip: tcps0x7f8db417 TCP connection closed 24-06-2015 12:28:41.988 UTC Debug connection_tracker.cpp:91: Connection 0x7f8db4172e38 has been destroyed 24-06-2015 12:28:41.988 UTC Verbose pjsip: tcps0x7f8db417 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) ^Z [7]+ Stopped tail -f /var/log/sprout/sprout_current.txt root@ubun3:~# tail -f /var/log/syslog Jun 24 19:20:01 ubun3 CRON[11106]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:21:01 ubun3 CRON[11296]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:22:01 ubun3 CRON[11486]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:23:01 ubun3 CRON[11675]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:24:01 ubun3 CRON[11865]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:25:01 ubun3 CRON[12056]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1) Jun 24 19:25:01 ubun3 CRON[12057]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:26:01 ubun3 CRON[12248]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:27:01 ubun3 CRON[12438]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:28:01 ubun3 CRON[12628]: (root) CMD (/usr/lib/sysstat/sadc 1 1 /var/log/sysstat/clearwater-sa`date +%d` > /dev/null 2>&1) Jun 24 19:28:38 ubun3 sprout[8367]: 1005 - Description: http://137.116.157.176:8888/impi/7107204018/av?impu=sip%3A7107204018%40example.com failed to communicate with HTTP server 137.116.157.176 with curl error No error code 0. @@Cause: An HTTP connection attempt failed to the specified server with the specified error code. @@Effect: This condition impacts the ability to register, subscribe, or make a call. @@Action: (1). Check to see if the specified host has failed. (2). Check to see if there is TCP connectivity to the host by using ping and/or Wireshark. ^Z [1]+ Stopped tail -f /var/log/syslog root@ubun3:/etc/clearwater# Thanks, Tam Vo
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
