Hello, We recently shifted our clearwater infrastructure to Open Stack.
We are facing an issue with the registration of a user. The following is the log at Sprout with log_level=5 I've highlighted the relevant error zones: REGISTER sip:ims.hom SIP/2.0 Via: SIP/2.0/TCP 192.168.1.41:54658 ;rport;branch=z9hG4bKPjQhihJs.dF7ZqIk473L9ayKtDZZo-H3kw Path: <sip:[email protected]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP 192.168.1.39:5060 ;rport=5060;received=192.168.1.39;branch=z9hG4bK107315516 From: <sip:[email protected]>;tag=1642292484 To: <sip:[email protected]> Call-ID: 1374014318 CSeq: 1 REGISTER Contact: <sip:[email protected]:5060 ;line=9002fc03804a36b>;+sip.instance="<urn:uuid:43be9c7e-a58e-11e4-955c-6ddd4f8d4915>" Authorization: Digest username="[email protected]", realm="ims.hom", nonce=" ", uri="sip:ims.hom", response=" ",integrity-protected=ip-assoc-pending Max-Forwards: 70 User-Agent: eXosip/3.1.0 Expires: 600000 Supported: path, gruu P-Visited-Network-ID: ims.hom Session-Expires: 600 Route: <sip:sprout.ims.hom:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 26-01-2015 19:05:38.589 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f8734097078 for worker threads 26-01-2015 19:05:38.589 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f8734097078 26-01-2015 19:05:38.589 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=1 (rdata0x7f8734097078) 26-01-2015 19:05:38.589 UTC Debug authentication.cpp:486: Authorization header in request 26-01-2015 19:05:38.589 UTC Debug memcachedstore.cpp:174: Key av\\[email protected]\ hashes to vbucket 41 via hash 0xbdd4da29 26-01-2015 19:05:38.589 UTC Debug memcachedstore.cpp:373: 1 read replicas for key av\\[email protected]\ *26-01-2015 19:05:38.589 UTC Debug memcachedstore.cpp:406: Attempt to read from replica 0 (connection 0x7f870c056860)26-01-2015 19:05:38.589 UTC Debug memcachedstore.cpp:449: Read for av\\[email protected]\ on replica 0 returned error 47 (SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY)26-01-2015 19:05:38.589 UTC Error memcachedstore.cpp:519: Failed to read data for av\\[email protected]\ from 1 replicas*26-01-2015 19:05:38.589 UTC Debug authentication.cpp:539: Verify authentication information in request 26-01-2015 19:05:38.589 UTC Warning authentication.cpp:204: Received an authentication request for [email protected] with nonce , but no matching AV found 26-01-2015 19:05:38.589 UTC Debug acr.cpp:48: Created ACR (0x7f870c1aa2b0) 26-01-2015 19:05:38.589 UTC Debug authentication.cpp:644: No authentication information in request or stale nonce, so reject with challenge 26-01-2015 19:05:38.589 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=1 (tdta0x7f870c1b6510) created 26-01-2015 19:05:38.589 UTC Debug pjutils.cpp:461: Private identity from authorization header = [email protected] 26-01-2015 19:05:38.589 UTC Debug httpresolver.cpp:70: HttpResolver::resolve for host hs.ims.hom, port 8888, family 2 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:501: Attempt to parse hs.ims.hom as IP address 26-01-2015 19:05:38.589 UTC Debug dnscachedresolver.cpp:179: Pulling 1 records from cache for hs.ims.hom A 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:349: Found 1 A/AAAA records, randomizing 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:491: 192.168.1.43:8888 transport 6 is not blacklisted 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:370: Added a server, now have 1 of 5 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:408: Adding 0 servers from blacklist 26-01-2015 19:05:38.589 UTC Debug baseresolver.cpp:501: Attempt to parse 192.168.1.43 as IP address 26-01-2015 19:05:38.589 UTC Debug httpconnection.cpp:553: Sending HTTP request : http://hs.ims.hom:8888/impi/user10%40ims.hom/av?impu=sip%3Auser10%40ims.hom (trying 192.168.1.43) 26-01-2015 19:05:38.591 UTC Debug httpconnection.cpp:568: Received HTTP response: status=200, doc={"digest":{"ha1":"4a4a6a1e2aad77dcb54cb43acd17c59d","realm":"ims.hom","qop":"auth"}} 26-01-2015 19:05:38.591 UTC Debug authentication.cpp:146: Digest specified 26-01-2015 19:05:38.591 UTC Debug authentication.cpp:309: Valid AV - generate challenge 26-01-2015 19:05:38.591 UTC Debug authentication.cpp:315: Create WWW-Authenticate header 26-01-2015 19:05:38.591 UTC Debug authentication.cpp:359: Add Digest information 26-01-2015 19:05:38.591 UTC Debug authentication.cpp:386: Write AV to store 26-01-2015 19:05:38.591 UTC Debug avstore.cpp:66: Set AV for [email protected] \2ebbd3a10aba9cfa {"branch":"z9hG4bKPjQhihJs.dF7ZqIk473L9ayKtDZZo-H3kw","digest":{"ha1":"4a4a6a1e2aad77dcb54cb43acd17c59d","qop":"auth","realm":"ims.hom"}} 26-01-2015 19:05:38.591 UTC Debug memcachedstore.cpp:540: Writing 138 bytes to table av key [email protected]\2ebbd3a10aba9cfa, CAS = 0, expiry = 40 26-01-2015 19:05:38.591 UTC Debug memcachedstore.cpp:174: Key av\\[email protected]\2ebbd3a10aba9cfa hashes to vbucket 34 via hash 0x325860a2 26-01-2015 19:05:38.591 UTC Debug memcachedstore.cpp:560: 1 write replicas for key av\\[email protected]\2ebbd3a10aba9cfa 26-01-2015 19:05:38.591 UTC Debug memcachedstore.cpp:609: Attempt conditional write to replica 0 (connection 0x7f870c056860), CAS = 0 *26-01-2015 19:05:38.591 UTC Debug memcachedstore.cpp:652: memcached_add command for av\\[email protected]\2ebbd3a10aba9cfa failed on replica 0, rc = 47 (SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY), expiry = 40(140217998993504) SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY, host: 10.129.2.112:11211 <http://10.129.2.112:11211> -> libmemcached/connect.cc:63326-01-2015 19:05:38.591 UTC Error memcachedstore.cpp:713: Failed to write data for av\\[email protected]\2ebbd3a10aba9cfa to 1 replicas26-01-2015 19:05:38.591 UTC Error avstore.cpp:71: Failed to write Authentication Vector for private_id [email protected]*26-01-2015 19:05:38.591 UTC Verbose stack.cpp:259: TX 545 bytes Response msg 401/REGISTER/cseq=1 (tdta0x7f870c1b6510) to TCP 192.168.1.41:54658: --start msg-- SIP/2.0 401 Unauthorized Via: SIP/2.0/TCP 192.168.1.41:54658 ;rport=54658;received=192.168.1.41;branch=z9hG4bKPjQhihJs.dF7ZqIk473L9ayKtDZZo-H3kw Via: SIP/2.0/UDP 192.168.1.39:5060 ;rport=5060;received=192.168.1.39;branch=z9hG4bK107315516 Call-ID: 1374014318 From: <sip:[email protected]>;tag=1642292484 To: <sip:[email protected]>;tag=z9hG4bKPjQhihJs.dF7ZqIk473L9ayKtDZZo-H3kw CSeq: 1 REGISTER WWW-Authenticate: Digest realm="ims.hom",nonce="2ebbd3a10aba9cfa",opaque="1fafe52f54443250",stale=true,algorithm=MD5,qop="auth" Content-Length: 0 --end msg-- 26-01-2015 19:05:38.591 UTC Debug pjsip: tdta0x7f870c1b Destroying txdata Response msg 401/REGISTER/cseq=1 (tdta0x7f870c1b6510) 26-01-2015 19:05:38.591 UTC Debug acr.cpp:82: Sending Null ACR (0x7f870c1aa2b0) 26-01-2015 19:05:38.591 UTC Debug acr.cpp:53: Destroyed ACR (0x7f870c1aa2b0) 26-01-2015 19:05:38.591 UTC Debug stack.cpp:208: Worker thread completed processing message 0x7f8734097078 26-01-2015 19:05:38.591 UTC Debug stack.cpp:214: Request latency = 1927us 26-01-2015 19:05:38.593 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=1 (rdata0x7f873400d328) 26-01-2015 19:05:38.593 UTC Verbose stack.cpp:243: RX 848 bytes Request msg REGISTER/cseq=1 (rdata0x7f873400d328) from TCP 192.168.1.41:42193: --start msg-- REGISTER sip:ims.hom SIP/2.0 Via: SIP/2.0/TCP 192.168.1.41:42193 ;rport;branch=z9hG4bKPjqvLAEWzN3k7PI663pnNLz6zgU9Sk5XJ6 Path: <sip:[email protected]:5058;transport=TCP;lr;ob> Via: SIP/2.0/UDP 192.168.1.39:5060 ;rport=5060;received=192.168.1.39;branch=z9hG4bK1731639894 From: <sip:[email protected]>;tag=1334365898 To: <sip:[email protected]> Call-ID: 1090655798 CSeq: 1 REGISTER Contact: <sip:[email protected]:5060;line=9002fc03804a36b> Authorization: Digest username="[email protected]", realm="ims.hom", nonce="2ebbd3a10aba9cfa", uri="sip:ims.hom", response="6da3503d6706fab2f9250a96ef9136b8", algorithm=MD5,integrity-protected=ip-assoc-pending Max-Forwards: 70 User-Agent: eXosip/3.1.0 Expires: 600000 P-Visited-Network-ID: ims.hom Session-Expires: 600 Route: <sip:sprout.ims.hom:5054;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 26-01-2015 19:05:38.593 UTC Debug stack.cpp:470: Queuing cloned received message 0x7f8734097078 for worker threads 26-01-2015 19:05:38.593 UTC Debug stack.cpp:206: Worker thread dequeue message 0x7f8734097078 26-01-2015 19:05:38.593 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=1 (rdata0x7f8734097078) 26-01-2015 19:05:38.593 UTC Debug authentication.cpp:486: Authorization header in request 26-01-2015 19:05:38.593 UTC Debug memcachedstore.cpp:174: Key av\\[email protected]\2ebbd3a10aba9cfa hashes to vbucket 34 via hash 0x325860a2 26-01-2015 19:05:38.593 UTC Debug memcachedstore.cpp:373: 1 read replicas for key av\\[email protected]\2ebbd3a10aba9cfa 26-01-2015 19:05:38.593 UTC Debug memcachedstore.cpp:406: Attempt to read from replica 0 (connection 0x7f87800cea30) *26-01-2015 19:05:38.593 UTC Debug memcachedstore.cpp:449: Read for av\\[email protected]\2ebbd3a10aba9cfa on replica 0 returned error 47 (SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY)26-01-2015 19:05:38.593 UTC Error memcachedstore.cpp:519: Failed to read data for av\\[email protected]\2ebbd3a10aba9cfa from 1 replicas*26-01-2015 19:05:38.593 UTC Debug authentication.cpp:539: Verify authentication information in request 26-01-2015 19:05:38.593 UTC Warning authentication.cpp:204: Received an authentication request for [email protected] with nonce 2ebbd3a10aba9cfa, but no matching AV found 26-01-2015 19:05:38.593 UTC Debug acr.cpp:48: Created ACR (0x7f878014fea0) 26-01-2015 19:05:38.593 UTC Debug authentication.cpp:644: No authentication information in request or stale nonce, so reject with challenge 26-01-2015 19:05:38.593 UTC Debug pjsip: endpoint Response msg 401/REGISTER/cseq=1 (tdta0x7f87801a2070) created 26-01-2015 19:05:38.593 UTC Debug pjutils.cpp:461: Private identity from authorization header = [email protected] 26-01-2015 19:05:38.593 UTC Debug httpresolver.cpp:70: HttpResolver::resolve for host hs.ims.hom, port 8888, family 2 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:501: Attempt to parse hs.ims.hom as IP address 26-01-2015 19:05:38.593 UTC Debug dnscachedresolver.cpp:179: Pulling 1 records from cache for hs.ims.hom A 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:349: Found 1 A/AAAA records, randomizing 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:491: 192.168.1.43:8888 transport 6 is not blacklisted 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:370: Added a server, now have 1 of 5 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:408: Adding 0 servers from blacklist 26-01-2015 19:05:38.593 UTC Debug baseresolver.cpp:501: Attempt to parse 192.168.1.43 as IP address 26-01-2015 19:05:38.593 UTC Debug httpconnection.cpp:553: Sending HTTP request : http://hs.ims.hom:8888/impi/user10%40ims.hom/av?impu=sip%3Auser10%40ims.hom (trying 192.168.1.43) 26-01-2015 19:05:38.594 UTC Debug httpconnection.cpp:568: Received HTTP response: status=200, doc={"digest":{"ha1":"4a4a6a1e2aad77dcb54cb43acd17c59d","realm":"ims.hom","qop":"auth"}} 26-01-2015 19:05:38.594 UTC Debug authentication.cpp:146: Digest specified 26-01-2015 19:05:38.594 UTC Debug authentication.cpp:309: Valid AV - generate challenge 26-01-2015 19:05:38.594 UTC Debug authentication.cpp:315: Create WWW-Authenticate header 26-01-2015 19:05:38.594 UTC Debug authentication.cpp:359: Add Digest information 26-01-2015 19:05:38.595 UTC Debug authentication.cpp:386: Write AV to store 26-01-2015 19:05:38.595 UTC Debug avstore.cpp:66: Set AV for [email protected] \256f5de87094a4d0 {"branch":"z9hG4bKPjqvLAEWzN3k7PI663pnNLz6zgU9Sk5XJ6","digest":{"ha1":"4a4a6a1e2aad77dcb54cb43acd17c59d","qop":"auth","realm":"ims.hom"}} 26-01-2015 19:05:38.595 UTC Debug memcachedstore.cpp:540: Writing 138 bytes to table av key [email protected]\256f5de87094a4d0, CAS = 0, expiry = 40 26-01-2015 19:05:38.595 UTC Debug memcachedstore.cpp:174: Key av\\[email protected]\256f5de87094a4d0 hashes to vbucket 127 via hash 0x8c22357f 26-01-2015 19:05:38.595 UTC Debug memcachedstore.cpp:560: 1 write replicas for key av\\[email protected]\256f5de87094a4d0 26-01-2015 19:05:38.595 UTC Debug memcachedstore.cpp:609: Attempt conditional write to replica 0 (connection 0x7f87800cea30), CAS = 0 *26-01-2015 19:05:38.595 UTC Debug memcachedstore.cpp:652: memcached_add command for av\\[email protected]\256f5de87094a4d0 failed on replica 0, rc = 47 (SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY), expiry = 40(140219945642544) SERVER HAS FAILED AND IS DISABLED UNTIL TIMED RETRY, host: 10.129.2.112:11211 <http://10.129.2.112:11211> -> libmemcached/connect.cc:63326-01-2015 19:05:38.595 UTC Error memcachedstore.cpp:713: Failed to write data for av\\[email protected]\256f5de87094a4d0 to 1 replicas26-01-2015 19:05:38.595 UTC Error avstore.cpp:71: Failed to write Authentication Vector for private_id [email protected] 19:05:38.595 UTC Verbose stack.cpp:259: TX 546 bytes Response msg 401/REGISTER/cseq=1 (tdta0x7f87801a2070) to TCP 192.168.1.41:42193 <http://192.168.1.41:42193>:* The Memcached server is unable to read/write the data and hence we are facing the problem. Can you please suggest some steps so that we can curb this issue. Thanks, Sushant Hiray, Senior Undergrad CSE, IIT Bombay _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
