Hi list,
I just manually deployed over a VMware platform five VMs respectively with bono, homer,sprout,homestead, and ellis, with no HSS lookups nor I-CSCF function. I tried to test it with clearwater-live-test but every tests fail with the following error: RuntimeError thrown: - Expected 200, got 401 I understood from old messages from the list that "401s are expected. The first time a client registers with Clearwater it will not provide authentication credentials. Sprout rejects the REGISTER message with a 401 response, containing an authentication challenge. The client then sends another REGISTER with credentials." But still, I cannot get what I'm missing here even with level 5 logs. Indeed, Bono seems to fail with both 403 and 401 errors. In the remaining of this email I put parts of the logs of each VM to illustrate my problem. *Sprout logs: * 29-09-2015 16:31:33.994 UTC Error hssconnection.cpp:147: Failed to get Authentication Vector for [email protected] 29-09-2015 16:31:34.005 UTC Error httpconnection.cpp:743: cURL failure with cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 404 29-09-2015 16:31:34.005 UTC Error hssconnection.cpp:147: Failed to get Authentication Vector for [email protected] [...] 29-09-2015 16:31:34.145 UTC Error hssconnection.cpp:147: Failed to get Authentication Vector for [email protected] 29-09-2015 16:31:39.414 UTC Status load_monitor.cpp:237: Maximum incoming request rate/second increased to 1675.491699 (based on a smoothed mean latency of 2810 and 0 upstream overload responses) 29-09-2015 16:31:41.596 UTC Error memcachedstore.cpp:719: Failed to write data for av\\[email protected]\0826351d69f0f550 to 1 replicas 29-09-2015 16:31:41.596 UTC Error avstore.cpp:84: Failed to write Authentication Vector for private_id [email protected] 29-09-2015 16:31:41.830 UTC Error memcachedstore.cpp:514: Failed to read data for av\\[email protected]\0826351d69f0f550 from 1 replicas 29-09-2015 16:31:41.830 UTC Warning authentication.cpp:242: Received an authentication request for [email protected] with nonce 0826351d69f0f550, but no matching AV found *Homer logs: * 29-09-2015 16:31:33.566 UTC DEBUG base.py:283: Writing response body: {} 29-09-2015 16:31:33.566 UTC INFO base.py:269: Sending 200 response to localhost for PUT http://http_homer/org.etsi.ngn.simservs/users/sip%3A6505550980%40my.local.domain/simservs.xml 29-09-2015 16:31:39.797 UTC INFO base.py:256: Received request from localhost - PUT http://http_homer/org.etsi.ngn.simservs/users/sip%3A6505550758%40my.local.domain/simservs.xml 29-09-2015 16:31:39.798 UTC INFO xsd.py:76: Performing XSD validation 29-09-2015 16:31:39.801 UTC DEBUG base.py:283: Writing response body: {} 29-09-2015 16:31:39.802 UTC INFO base.py:269: Sending 200 response to localhost for PUT http://http_homer/org.etsi.ngn.simservs/users/sip%3A6505550758%40my.local.domain/simservs.xml 29-09-2015 16:31:43.436 UTC INFO base.py:256: Received request from localhost - PUT http://http_homer/org.etsi.ngn.simservs/users/sip%3A6505550048%40my.local.domain/simservs.xml 29-09-2015 16:31:43.436 UTC INFO xsd.py:76: Performing XSD validation 29-09-2015 16:31:43.439 UTC DEBUG base.py:283: Writing response body: {} *Homestead-prov logs: * 29-09-2015 16:31:33.538 UTC INFO base.py:269: Sending 200 response to localhost for PUT http://http_homestead_prov/irs/1004b727-c478-4123-98f6-9b63802c6a8c/service_profiles/19e5a738-f3ec-4664-bd2b-958ab5a8310a/filter_criteria 29-09-2015 16:31:34.183 UTC INFO base.py:256: Received request from localhost - PUT http://http_homestead_prov/private/6505550473%40my.local.domain 29-09-2015 16:31:34.184 UTC DEBUG models.py:303: Create private ID6505550473 @my.local.domain 29-09-2015 16:31:34.185 UTC DEBUG cache.py:85: Put private ID '[email protected]' into cache with AV: {'digest': {'ha1': u'33accced67a669ca7b3d7e96640ef7f4', 'realm': u'my.local.domain', 'qop': 'auth'}} 29-09-2015 16:31:34.187 UTC INFO base.py:269: Sending 200 response to localhost for PUT http://http_homestead_prov/private/6505550473%40my.local.domain *Homestead logs: * 29-09-2015 16:31:33.999 UTC Debug cassandra_store.cpp:731: Failed ONE read for get_columns. Try QUORUM 29-09-2015 16:31:34.000 UTC Debug cassandra_store.cpp:432: Cassandra request failed: rc=2, Row [email protected] not present in column_family impi 29-09-2015 16:31:34.000 UTC Debug handlers.cpp:196: Cache query failed - reject request 29-09-2015 16:31:34.000 UTC Debug handlers.cpp:201: No cached av found for private ID [email protected], public ID sip:[email protected] - reject 29-09-2015 16:31:34.000 UTC Verbose httpstack.cpp:69: Sending response 404 to request for URL /impi/2010018950%40my.local.domain/av, args impu=sip%3A2010018950%40my.local.domain 29-09-2015 16:31:34.000 UTC Verbose httpstack.cpp:286: Process request for URL /impi/2010070984%40my.local.domain/av, args impu=sip%3A2010070984%40my. local.domain 29-09-2015 16:31:34.000 UTC Debug handlers.cpp:147: Parsed HTTP request: private ID [email protected], public ID sip:[email protected], scheme Unknown, authorization 29-09-2015 16:31:34.000 UTC Debug handlers.cpp:167: Querying cache for authentication vector for [email protected]/ sip:[email protected] 29-09-2015 16:31:34.000 UTC Debug cassandra_store.cpp:279: Getting thread-local Client 29-09-2015 16:31:34.000 UTC Debug cache.cpp:673: Looking for authentication vector for [email protected] 29-09-2015 16:31:34.000 UTC Debug cache.cpp:686: Checking public ID sip:[email protected] 29-09-2015 16:31:34.000 UTC Debug cache.cpp:696: Issuing cache query 29-09-2015 16:31:34.000 UTC Debug cassandra_store.cpp:731: Failed ONE read for get_columns. Try QUORUM 29-09-2015 16:31:34.001 UTC Verbose httpstack.cpp:286: Process request for URL /impi/2010052484%40my.local.domain/av, args impu=sip%3A2010052484%40my. local.domain 29-09-2015 16:31:34.001 UTC Debug handlers.cpp:147: Parsed HTTP request: private ID [email protected], public ID sip:[email protected], scheme Unknown, authorization *Bono logs: * 29-09-2015 16:31:33.996 UTC Call-Disconnected: CALL_ID=2010076236/// [email protected] REASON=403 29-09-2015 16:31:34.008 UTC Call-Disconnected: CALL_ID=2010018950/// [email protected] REASON=403 29-09-2015 16:31:34.008 UTC Call-Disconnected: CALL_ID=2010070984/// [email protected] REASON=403 29-09-2015 16:31:34.008 UTC Call-Disconnected: CALL_ID=2010052484/// [email protected] REASON=403 29-09-2015 16:31:34.013 UTC Call-Disconnected: CALL_ID=2010023276/// [email protected] REASON=403 29-09-2015 16:31:34.013 UTC Call-Disconnected: CALL_ID=2010004256/// [email protected] REASON=403 29-09-2015 16:31:34.014 UTC Call-Disconnected: CALL_ID=2010076066/// [email protected] REASON=403 29-09-2015 16:31:34.014 UTC Call-Disconnected: CALL_ID=2010040994/// [email protected] REASON=403 29-09-2015 16:31:34.020 UTC Call-Disconnected: CALL_ID=2010047262/// [email protected] REASON=403 29-09-2015 16:31:34.021 UTC Call-Disconnected: CALL_ID=2010070408/// [email protected] REASON=403 29-09-2015 16:31:34.024 UTC Call-Disconnected: CALL_ID=2010001186/// [email protected] REASON=403 29-09-2015 16:31:34.030 UTC Call-Disconnected: CALL_ID=2010080220/// [email protected] REASON=403 29-09-2015 16:31:34.037 UTC Call-Disconnected: CALL_ID=2010026340/// [email protected] REASON=403 29-09-2015 16:31:34.049 UTC Call-Disconnected: CALL_ID=2010059662/// [email protected] REASON=403 29-09-2015 16:31:34.051 UTC Call-Disconnected: CALL_ID=2010007964/// [email protected] REASON=403 29-09-2015 16:31:34.059 UTC Call-Disconnected: CALL_ID=2010001412/// [email protected] REASON=403 29-09-2015 16:31:34.084 UTC Call-Disconnected: CALL_ID=2010048846/// [email protected] REASON=403 29-09-2015 16:31:34.085 UTC Call-Disconnected: CALL_ID=2010031554/// [email protected] REASON=403 29-09-2015 16:31:34.092 UTC Call-Disconnected: CALL_ID=2010083556/// [email protected] REASON=403 29-09-2015 16:31:34.092 UTC Call-Disconnected: CALL_ID=2010025210/// [email protected] REASON=403 29-09-2015 16:31:34.110 UTC Call-Disconnected: CALL_ID=2010060732/// [email protected] REASON=403 29-09-2015 16:31:34.112 UTC Call-Disconnected: CALL_ID=2010020690/// [email protected] REASON=403 29-09-2015 16:31:34.120 UTC Call-Disconnected: CALL_ID=2010065600/// [email protected] REASON=403 29-09-2015 16:31:34.123 UTC Call-Disconnected: CALL_ID=2010058752/// [email protected] REASON=403 29-09-2015 16:31:34.129 UTC Call-Disconnected: CALL_ID=2010070682/// [email protected] REASON=403 29-09-2015 16:31:34.129 UTC Call-Disconnected: CALL_ID=2010046438/// [email protected] REASON=403 29-09-2015 16:31:34.142 UTC Call-Disconnected: CALL_ID=2010049994/// [email protected] REASON=403 29-09-2015 16:31:34.144 UTC Call-Disconnected: CALL_ID=2010070470/// [email protected] REASON=403 29-09-2015 16:31:34.146 UTC Call-Disconnected: CALL_ID=2010024050/// [email protected] REASON=403 29-09-2015 16:31:41.598 UTC Call-Disconnected: CALL_ID= 17745eb3f9e50ecb8155e83aea81edae REASON=401 29-09-2015 16:31:41.835 UTC Call-Disconnected: CALL_ID= 17745eb3f9e50ecb8155e83aea81edae REASON=401 29-09-2015 16:31:42.136 UTC Call-Disconnected: CALL_ID= 17745eb3f9e50ecb8155e83aea81edae REASON=401 29-09-2015 16:31:42.437 UTC Call-Disconnected: CALL_ID= 17745eb3f9e50ecb8155e83aea81edae REASON=401 29-09-2015 16:31:45.312 UTC Call-Disconnected: CALL_ID= 88a59417552efe9582128c1c9d134862 REASON=401 29-09-2015 16:31:45.320 UTC Call-Disconnected: CALL_ID= 88a59417552efe9582128c1c9d134862 REASON=401 29-09-2015 16:31:45.327 UTC Call-Disconnected: CALL_ID= 88a59417552efe9582128c1c9d134862 REASON=401 29-09-2015 16:31:45.334 UTC Call-Disconnected: CALL_ID= 88a59417552efe9582128c1c9d134862 REASON=401 29-09-2015 16:31:51.173 UTC Call-Disconnected: CALL_ID= a716eed59a862336ae71d2a329b77400 REASON=401 29-09-2015 16:31:51.465 UTC Call-Disconnected: CALL_ID= a716eed59a862336ae71d2a329b77400 REASON=401 29-09-2015 16:31:51.766 UTC Call-Disconnected: CALL_ID= a716eed59a862336ae71d2a329b77400 REASON=401 *Ellis logs: * 29-09-2015 16:31:32.727 UTC DEBUG utils.py:94: Still expecting 0 callbacks 29-09-2015 16:31:34.324 UTC DEBUG numbers.py:121: Number allocation API call (PSTN = false) 29-09-2015 16:31:34.650 UTC DEBUG numbers.py:134: Allocating a non-PSTN number 29-09-2015 16:31:34.653 UTC DEBUG numbers.py:148: Fetched e7d0bf0c-e00a-41c8-8bc7-5377aa76dc97 29-09-2015 16:31:35.426 UTC DEBUG numbers.py:160: Updated the owner 29-09-2015 16:31:35.427 UTC DEBUG numbers.py:130: SIP URI sip:6505550758 @my.local.domain 29-09-2015 16:31:39.686 UTC DEBUG numbers.py:159: Populating other servers... 29-09-2015 16:31:39.686 UTC DEBUG numbers.py:170: About to create private ID at Homestead 29-09-2015 16:31:39.686 UTC WARNING homestead.py:279: Passing SIP password in the clear over http 29-09-2015 16:31:39.698 UTC WARNING homestead.py:279: Passing SIP password in the clear over http 29-09-2015 16:31:39.704 UTC WARNING homestead.py:279: Passing SIP password in the clear over http 29-09-2015 16:31:39.720 UTC DEBUG numbers.py:175: Created private ID at Homestead 29-09-2015 16:31:39.721 UTC WARNING homestead.py:279: Passing SIP password in the clear over http 29-09-2015 16:31:39.794 UTC DEBUG utils.py:84: OK HTTP response. HTTPResponse(code=200,request_time=0.015350818634033203,buffer=<_io.BytesIO object at 0x7ff1a10d6f50>,_body=None,time_info={},request=<tornado.httpclient.HTTPRequest object at 0x7ff1a1070d50>,effective_url=' http://hs.my.local.domain:8889/private/6505550758%40my.local.domain/associated_implicit_registration_sets/1ed1c2eb-745d-4d53-8be2-68116882268e',headers={'Date': 'Tue, 29 Sep 2015 16:31:39 GMT', 'Content-Length': '0', 'Content-Type': 'text/html; charset=UTF-8', 'Connection': 'close', 'Server': 'nginx/1.4.6 (Ubuntu)'},error=None) 29-09-2015 16:31:39.794 UTC DEBUG utils.py:94: Still expecting 2 callbacks 29-09-2015 16:31:39.803 UTC DEBUG utils.py:94: Still expecting 1 callbacks 29-09-2015 16:31:39.823 UTC DEBUG utils.py:84: OK HTTP response. HTTPResponse(code=200,request_time=0.030350208282470703,buffer=<_io.BytesIO object at 0x7ff1a10d6d10>,_body=None,time_info={},request=<tornado.httpclient.HTTPRequest object at 0x7ff1a10705d0>,effective_url=' http://hs.my.local.domain:8889/irs/1ed1c2eb-745d-4d53-8be2-68116882268e/service_profiles/113003da-f6f3-4efa-8612-bcb4f5be908b/filter_criteria',headers={'Date': 'Tue, 29 Sep 2015 16:31:39 GMT', 'Content-Length': '0', 'Content-Type': 'text/html; charset=UTF-8', 'Connection': 'close', 'Server': 'nginx/1.4.6 (Ubuntu)'},error=None) 29-09-2015 16:31:39.823 UTC DEBUG utils.py:92: All requests successful. Many thanks for your help ! PS: Let me know if the logs are not clear enough or if I should put them in attachment.
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
