Re: [Clearwater] SIP Registration Failure: 403 Forbidden

[Eleanor Merry]

Hi Simon, 

This looks like you're hitting an issue with the system time. 

The authentication vector is successfully written to memcached ("Debug 
memcachedstore.cpp:542: Conditional write 
succeeded to replica 0") - however it's missing when Sprout comes to read it 
back ("Read for 
av\\0000001...@example.com\0a55eab763c3eaed on replica 0 returned NOTFOUND"). 
This suggests that it's been expired. 

We've seen this issue before where there's been an NTP step change shortly 
after memcached has started - please see 
https://github.com/Metaswitch/cpp-common/issues/160 for more details. 

To work around this, you can kill and restart memcached. Alternatively, a fix 
to use relative time rather than absolute time for memcached expiry has been 
released, so if you update your node to the latest code you can use this fix 
(we recommend running up to date code as well!). 

There is also an issue where the Chronos timer 
(https://github.com/Metaswitch/chronos) is triggering immediately. This likely 
has the same cause (and so can be fixed by restarting Chronos) - but it would 
be really useful if you could send me the Chronos logs to check. These are in 
/var/log/chronos, and you turn on debug logging by adding the following to 
/etc/clearwater/chronos.conf:
[logging]
level = 5

On Windows, the base Zoiper UI only lets you set three parameters as you 
discovered.  But you should be able to do Settings > Preferences and set the 
Auth username for the account that you set up.

Thanks, 

Ellie


-----Original Message-----
From: simon connolly [mailto:sconn...@hotmail.com] 
Sent: 29 September 2014 09:53
To: Eleanor Merry; clearwater@lists.projectclearwater.org
Subject: Re: [Clearwater] SIP Registration Failure: 403 Forbidden

Hi

Zoiper version is 3.6.25251 running on windows 7

here is the log trace requested

OPTIONS sip:poll-sip@192.168.20.68:5054 SIP/2.0
Via: SIP/2.0/TCP 192.168.20.68;rport;branch=z9hG4bK-2787
Max-Forwards: 2
To: <sip:poll-sip@192.168.20.68:5054>
From: poll-sip <sip:poll-sip@192.168.20.68>;tag=2787
Call-ID: poll-sip-2787
CSeq: 2787 OPTIONS
Contact: <sip:192.168.20.68>
Accept: application/sdp
Content-Length: 0
User-Agent: poll-sip


--end msg--
29-09-2014 08:45:59.903 UTC Debug statistic.cpp:103: Send new value for 
statistic incoming_requests, size 1
29-09-2014 08:45:59.903 UTC Debug zmq_lvc.cpp:167: Update to incoming_requests 
statistic
29-09-2014 08:45:59.903 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 
0x7f893c02a170
29-09-2014 08:45:59.903 UTC Debug stack.cpp:425: Queuing cloned received 
message 0x7f8924095e28 for worker threads
29-09-2014 08:45:59.903 UTC Debug statistic.cpp:103: Send new value for 
statistic queue_size, size 5
29-09-2014 08:45:59.903 UTC Debug zmq_lvc.cpp:167: Update to queue_size 
statistic
29-09-2014 08:45:59.903 UTC Debug zmq_lvc.cpp:250: Clearing message cache for 
0x7f893c0334b0
29-09-2014 08:45:59.903 UTC Debug stack.cpp:195: Worker thread dequeue message 
0x7f8924095e28
29-09-2014 08:45:59.903 UTC Debug pjsip: sip_endpoint.c Distributing rdata to 
modules: Request msg OPTIONS/cseq=2787 (rdata0x7f8924095e28)
29-09-2014 08:45:59.903 UTC Debug pjsip:       endpoint Response msg 
200/OPTIONS/cseq=2787 (tdta0x7f8938000900) created
29-09-2014 08:45:59.904 UTC Verbose stack.cpp:248: TX 276 bytes Response msg
200/OPTIONS/cseq=2787 (tdta0x7f8938000900) to TCP 192.168.20.68:50873:
--start msg--

SIP/2.0 200 OK
Via: SIP/2.0/TCP
192.168.20.68;rport=50873;received=192.168.20.68;branch=z9hG4bK-2787
Call-ID: poll-sip-2787
From: "poll-sip" <sip:poll-sip@192.168.20.68>;tag=2787
To: <sip:poll-sip@192.168.20.68>;tag=z9hG4bK-2787
CSeq: 2787 OPTIONS
Content-Length:  0


--end msg--
29-09-2014 08:45:59.904 UTC Debug pjsip: tdta0x7f893800 Destroying txdata 
Response msg 200/OPTIONS/cseq=2787 (tdta0x7f8938000900)
29-09-2014 08:45:59.904 UTC Debug stack.cpp:197: Worker thread completed 
processing message 0x7f8924095e28
29-09-2014 08:45:59.904 UTC Debug stack.cpp:203: Request latency = 133us
29-09-2014 08:45:59.904 UTC Debug statistic.cpp:103: Send new value for 
statistic latency_us, size 5
29-09-2014 08:45:59.904 UTC Debug zmq_lvc.cpp:167: Update to latency_us 
statistic
29-09-2014 08:45:59.904 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c013100
29-09-2014 08:46:00.912 UTC Verbose pjsip: tcps0x7f892409 TCP connection 
closed
29-09-2014 08:46:00.914 UTC Debug connection_tracker.cpp:91: Connection 
0x7f89240914a8 has been destroyed
29-09-2014 08:46:00.914 UTC Verbose pjsip: tcps0x7f892409 TCP transport 
destroyed with reason 70016: End of file (PJ_EEOF)
29-09-2014 08:46:01.517 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg REGISTER/cseq=1 (rdata0x7f892406ede8)
29-09-2014 08:46:01.517 UTC Verbose stack.cpp:232: RX 814 bytes Request msg 
REGISTER/cseq=1 (rdata0x7f892406ede8) from TCP 192.168.20.68:49358:
--start msg--

REGISTER sip:example.com SIP/2.0
Path: sip:CXGoU0eTWN@192.168.20.68:5058;transport=TCP;lr;ob
Via: SIP/2.0/TCP 
192.168.20.68:49358;rport;branch=z9hG4bKPj4ioEyxnzVoaJN5mYM9xcW.suEUajmgKJ
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-6a40613a09e5ea33-1---d8754z-
Max-Forwards: 69
Contact: <sip:0000001005@192.168.20.50:5060;rinstance=8a6c503517a7e66d>
To: "1005" <sip:0000001...@example.com>
From: "1005" <sip:0000001...@example.com>;tag=1010416b
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
CSeq: 1 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, 
INFO
User-Agent: X-Lite release 4.5.5  stamp 71236
Session-Expires: 600
Route: <sip:192.168.20.68:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
29-09-2014 08:46:01.517 UTC Debug stack.cpp:425: Queuing cloned received 
message 0x7f8924095e28 for worker threads
29-09-2014 08:46:01.517 UTC Debug stack.cpp:195: Worker thread dequeue 
message 0x7f8924095e28
29-09-2014 08:46:01.517 UTC Debug pjsip: sip_endpoint.c Distributing rdata 
to modules: Request msg REGISTER/cseq=1 (rdata0x7f8924095e28)
29-09-2014 08:46:01.517 UTC Debug acr.cpp:48: Created ACR (0x7f893403ab10)
29-09-2014 08:46:01.517 UTC Debug authentication.cpp:650: No authentication 
information in request or stale nonce, so reject with challenge
29-09-2014 08:46:01.517 UTC Debug pjsip:       endpoint Response msg 
401/REGISTER/cseq=1 (tdta0x7f89340009c0) created
29-09-2014 08:46:01.517 UTC Debug pjutils.cpp:439: Private identity 
defaulted from public identity = 0000001...@example.com
29-09-2014 08:46:01.518 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x7f893407fe90
29-09-2014 08:46:01.518 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 8888, family 2
29-09-2014 08:46:01.518 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.518 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.518 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : 
http://192.168.20.68:8888/impi/0000001005%40example.com/av?impu=sip%3A0000001005%40example.com
 
(trying 192.168.20.68) on new connection
29-09-2014 08:46:01.520 UTC Debug httpconnection.cpp:545: Received HTTP 
response : 
{"digest":{"ha1":"78b9f6376646ef8411472d40530519e0","realm":"example.com","qop":"auth"}}
29-09-2014 08:46:01.520 UTC Debug statistic.cpp:103: Send new value for 
statistic connected_homesteads, size 2
29-09-2014 08:46:01.520 UTC Debug zmq_lvc.cpp:167: Update to 
connected_homesteads statistic
29-09-2014 08:46:01.520 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c009dc0
29-09-2014 08:46:01.520 UTC Debug statistic.cpp:103: Send new value for 
statistic hss_latency_us, size 5
29-09-2014 08:46:01.520 UTC Debug zmq_lvc.cpp:167: Update to hss_latency_us 
statistic
29-09-2014 08:46:01.521 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c017a90
29-09-2014 08:46:01.521 UTC Debug statistic.cpp:103: Send new value for 
statistic hss_digest_latency_us, size 5
29-09-2014 08:46:01.521 UTC Debug zmq_lvc.cpp:167: Update to 
hss_digest_latency_us statistic
29-09-2014 08:46:01.521 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c01c430
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:147: Digest specified
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:309: Valid AV - 
generate challenge
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:315: Create 
WWW-Authenticate header
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:361: Add Digest 
information
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:390: Write AV to store
29-09-2014 08:46:01.521 UTC Debug avstore.cpp:66: Set AV for 
0000001...@example.com\0a55eab763c3eaed
{"branch":"z9hG4bKPj4ioEyxnzVoaJN5mYM9xcW.suEUajmgKJ","digest":{"ha1":"78b9f6376646ef8411472d40530519e0","qop":"auth","realm":"example.com"}}

29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:449: Writing 142 bytes 
to table av key 0000001...@example.com\0a55eab763c3eaed, CAS = 0, expiry = 
40
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:175: Set up new view 1 
for thread
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:184: Setting up server 
0 for connection 0x7f893404e610 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS)
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:186: Set up connection 
0x7f8934051730 to server 192.168.20.68:11211
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:228: Setting server to 
IP address 192.168.20.68 port 11211
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\0a55eab763c3eaed hashes to vbucket 104 via hash 
0x1a977768
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:468: 1 write replicas 
for key av\\0000001...@example.com\0a55eab763c3eaed
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:506: Attempt 
conditional write to replica 0 (connection 0x7f8934051730), CAS = 0
29-09-2014 08:46:01.521 UTC Debug memcachedstore.cpp:542: Conditional write 
succeeded to replica 0
29-09-2014 08:46:01.521 UTC Debug authentication.cpp:400: Sending {"impi": 
"0000001...@example.com", "impu": "sip:0000001...@example.com", "nonce": 
"0a55eab763c3eaed"} to Chronos to set AV timer
29-09-2014 08:46:01.521 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x7f89340bbe30
29-09-2014 08:46:01.523 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 7253, family 2
29-09-2014 08:46:01.523 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.523 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.523 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : http://192.168.20.68:7253/timers (trying 192.168.20.68) on new 
connection
29-09-2014 08:46:01.523 UTC Debug httpconnection.cpp:825: Received header 
http/1.1200ok with value
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:825: Received header 
location with value /timers/000aa3a6400000068000000800600500
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:825: Received header 
date with value Mon,29Sep201408:46:01GMT
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:825: Received header 
content-length with value 0
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:825: Received header 
content-type with value text/html;charset=ISO-8859-1
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:825: Received header 
with value
29-09-2014 08:46:01.524 UTC Debug httpconnection.cpp:545: Received HTTP 
response :
29-09-2014 08:46:01.524 UTC Verbose stack.cpp:248: TX 630 bytes Response msg 
401/REGISTER/cseq=1 (tdta0x7f89340009c0) to TCP 192.168.20.68:49358:
--start msg--

SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 
192.168.20.68:49358;rport=49358;received=192.168.20.68;branch=z9hG4bKPj4ioEyxnzVoaJN5mYM9xcW.suEUajmgKJ
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-6a40613a09e5ea33-1---d8754z-
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
From: "1005" <sip:0000001...@example.com>;tag=1010416b
To: "1005" 
<sip:0000001...@example.com>;tag=z9hG4bKPj4ioEyxnzVoaJN5mYM9xcW.suEUajmgKJ
CSeq: 1 REGISTER
WWW-Authenticate: Digest 
realm="example.com",nonce="0a55eab763c3eaed",opaque="2103703938968978",algorithm=MD5,qop="auth"
Content-Length:  0


--end msg--
29-09-2014 08:46:01.524 UTC Debug pjsip: tdta0x7f893400 Destroying txdata 
Response msg 401/REGISTER/cseq=1 (tdta0x7f89340009c0)
29-09-2014 08:46:01.524 UTC Debug acr.cpp:82: Sending Null ACR 
(0x7f893403ab10)
29-09-2014 08:46:01.524 UTC Debug acr.cpp:53: Destroyed ACR (0x7f893403ab10)
29-09-2014 08:46:01.524 UTC Debug stack.cpp:197: Worker thread completed 
processing message 0x7f8924095e28
29-09-2014 08:46:01.524 UTC Debug stack.cpp:203: Request latency = 6849us
29-09-2014 08:46:01.531 UTC Verbose httpstack.cpp:259: Process request for 
URL /authentication-timeout, args (null)
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\0a55eab763c3eaed hashes to vbucket 104 via hash 
0x1a977768
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:304: 1 read replicas 
for key av\\0000001...@example.com\0a55eab763c3eaed
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:337: Attempt to read 
from replica 0 (connection 0x7f8930010970)
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:343: Fetch result
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:373: Read for 
av\\0000001...@example.com\0a55eab763c3eaed on replica 0 returned NOTFOUND
29-09-2014 08:46:01.531 UTC Debug memcachedstore.cpp:413: At least one 
replica returned not found, so return NOT_FOUND
29-09-2014 08:46:01.531 UTC Warning handlers.cpp:573: Could not find AV for 
0000001...@example.com:0a55eab763c3eaed when checking authentication timeout
29-09-2014 08:46:01.531 UTC Debug handlers.cpp:167: Unable to handle 
callback from Chronos
29-09-2014 08:46:01.531 UTC Verbose httpstack.cpp:68: Sending response 500 
to request for URL /authentication-timeout, args (null)
29-09-2014 08:46:01.532 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg REGISTER/cseq=2 (rdata0x7f89240778d8)
29-09-2014 08:46:01.532 UTC Verbose stack.cpp:232: RX 1094 bytes Request msg 
REGISTER/cseq=2 (rdata0x7f89240778d8) from TCP 192.168.20.68:40950:
--start msg--

REGISTER sip:example.com SIP/2.0
Path: sip:CXGoU0eTWN@192.168.20.68:5058;transport=TCP;lr;ob
Via: SIP/2.0/TCP 
192.168.20.68:40950;rport;branch=z9hG4bKPjzNFLAAN8lX9vyYgd-so-0.vLlfRKsJ64
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-885d2d18b696975b-1---d8754z-
Max-Forwards: 69
Contact: <sip:0000001005@192.168.20.50:5060;rinstance=8a6c503517a7e66d>
To: "1005" <sip:0000001...@example.com>
From: "1005" <sip:0000001...@example.com>;tag=1010416b
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
CSeq: 2 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, 
INFO
User-Agent: X-Lite release 4.5.5  stamp 71236
Authorization: Digest username="0000001...@example.com", 
realm="example.com", nonce="0a55eab763c3eaed", uri="sip:example.com", 
response="edaaac248b0ef5967db9ec09d4c387d3", algorithm=MD5, 
cnonce="8265ecf23493a455bcfb7f47d7eabe4e", opaque="2103703938968978", 
qop=auth, nc=00000001
Session-Expires: 600
Route: <sip:192.168.20.68:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
29-09-2014 08:46:01.532 UTC Debug stack.cpp:425: Queuing cloned received 
message 0x7f8924095e28 for worker threads
29-09-2014 08:46:01.532 UTC Debug stack.cpp:195: Worker thread dequeue 
message 0x7f8924095e28
29-09-2014 08:46:01.532 UTC Debug pjsip: sip_endpoint.c Distributing rdata 
to modules: Request msg REGISTER/cseq=2 (rdata0x7f8924095e28)
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:175: Set up new view 1 
for thread
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:184: Setting up server 
0 for connection 0x7f893c055e60 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS)
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:186: Set up connection 
0x7f893c055ec0 to server 192.168.20.68:11211
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:228: Setting server to 
IP address 192.168.20.68 port 11211
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\0a55eab763c3eaed hashes to vbucket 104 via hash 
0x1a977768
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:304: 1 read replicas 
for key av\\0000001...@example.com\0a55eab763c3eaed
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:337: Attempt to read 
from replica 0 (connection 0x7f893c055ec0)
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:343: Fetch result
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:373: Read for 
av\\0000001...@example.com\0a55eab763c3eaed on replica 0 returned NOTFOUND
29-09-2014 08:46:01.532 UTC Debug memcachedstore.cpp:413: At least one 
replica returned not found, so return NOT_FOUND
29-09-2014 08:46:01.532 UTC Debug authentication.cpp:531: Verify 
authentication information in request
29-09-2014 08:46:01.532 UTC Warning authentication.cpp:205: Received an 
authentication request for 0000001...@example.com with nonce 
0a55eab763c3eaed, but no matching AV found
29-09-2014 08:46:01.532 UTC Debug acr.cpp:48: Created ACR (0x7f893c05def0)
29-09-2014 08:46:01.533 UTC Debug authentication.cpp:650: No authentication 
information in request or stale nonce, so reject with challenge
29-09-2014 08:46:01.533 UTC Debug pjsip:       endpoint Response msg 
401/REGISTER/cseq=2 (tdta0x7f893c05df10) created
29-09-2014 08:46:01.533 UTC Debug pjutils.cpp:432: Private identity from 
authorization header = 0000001...@example.com
29-09-2014 08:46:01.533 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x7f893c05efa0
29-09-2014 08:46:01.534 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 8888, family 2
29-09-2014 08:46:01.534 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.534 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.534 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : 
http://192.168.20.68:8888/impi/0000001005%40example.com/av?impu=sip%3A0000001005%40example.com
 
(trying 192.168.20.68) on new connection
29-09-2014 08:46:01.536 UTC Debug httpconnection.cpp:545: Received HTTP 
response : 
{"digest":{"ha1":"78b9f6376646ef8411472d40530519e0","realm":"example.com","qop":"auth"}}
29-09-2014 08:46:01.536 UTC Debug statistic.cpp:103: Send new value for 
statistic connected_homesteads, size 2
29-09-2014 08:46:01.536 UTC Debug zmq_lvc.cpp:167: Update to 
connected_homesteads statistic
29-09-2014 08:46:01.536 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c009dc0
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:147: Digest specified
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:309: Valid AV - 
generate challenge
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:315: Create 
WWW-Authenticate header
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:361: Add Digest 
information
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:390: Write AV to store
29-09-2014 08:46:01.536 UTC Debug avstore.cpp:66: Set AV for 
0000001...@example.com\20f6cb34339810b4
{"branch":"z9hG4bKPjzNFLAAN8lX9vyYgd-so-0.vLlfRKsJ64","digest":{"ha1":"78b9f6376646ef8411472d40530519e0","qop":"auth","realm":"example.com"}}

29-09-2014 08:46:01.536 UTC Debug memcachedstore.cpp:449: Writing 142 bytes 
to table av key 0000001...@example.com\20f6cb34339810b4, CAS = 0, expiry = 
40
29-09-2014 08:46:01.536 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\20f6cb34339810b4 hashes to vbucket 31 via hash 
0x834b2a1f
29-09-2014 08:46:01.536 UTC Debug memcachedstore.cpp:468: 1 write replicas 
for key av\\0000001...@example.com\20f6cb34339810b4
29-09-2014 08:46:01.536 UTC Debug memcachedstore.cpp:506: Attempt 
conditional write to replica 0 (connection 0x7f893c055ec0), CAS = 0
29-09-2014 08:46:01.536 UTC Debug memcachedstore.cpp:542: Conditional write 
succeeded to replica 0
29-09-2014 08:46:01.536 UTC Debug authentication.cpp:400: Sending {"impi": 
"0000001...@example.com", "impu": "sip:0000001...@example.com", "nonce": 
"20f6cb34339810b4"} to Chronos to set AV timer
29-09-2014 08:46:01.536 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x7f893c097ff0
29-09-2014 08:46:01.537 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 7253, family 2
29-09-2014 08:46:01.537 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.537 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.537 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : http://192.168.20.68:7253/timers (trying 192.168.20.68) on new 
connection
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
http/1.1200ok with value
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
location with value /timers/000aa3a9c00000078000000800600500
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
date with value Mon,29Sep201408:46:01GMT
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
content-length with value 0
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
content-type with value text/html;charset=ISO-8859-1
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:825: Received header 
with value
29-09-2014 08:46:01.538 UTC Debug httpconnection.cpp:545: Received HTTP 
response :
29-09-2014 08:46:01.538 UTC Verbose stack.cpp:248: TX 630 bytes Response msg 
401/REGISTER/cseq=2 (tdta0x7f893c05df10) to TCP 192.168.20.68:40950:
--start msg--

SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 
192.168.20.68:40950;rport=40950;received=192.168.20.68;branch=z9hG4bKPjzNFLAAN8lX9vyYgd-so-0.vLlfRKsJ64
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-885d2d18b696975b-1---d8754z-
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
From: "1005" <sip:0000001...@example.com>;tag=1010416b
To: "1005" 
<sip:0000001...@example.com>;tag=z9hG4bKPjzNFLAAN8lX9vyYgd-so-0.vLlfRKsJ64
CSeq: 2 REGISTER
WWW-Authenticate: Digest 
realm="example.com",nonce="20f6cb34339810b4",opaque="38e5df0d3d3d7da1",algorithm=MD5,qop="auth"
Content-Length:  0


--end msg--
29-09-2014 08:46:01.538 UTC Debug pjsip: tdta0x7f893c05 Destroying txdata 
Response msg 401/REGISTER/cseq=2 (tdta0x7f893c05df10)
29-09-2014 08:46:01.538 UTC Debug acr.cpp:82: Sending Null ACR 
(0x7f893c05def0)
29-09-2014 08:46:01.538 UTC Debug acr.cpp:53: Destroyed ACR (0x7f893c05def0)
29-09-2014 08:46:01.539 UTC Debug stack.cpp:197: Worker thread completed 
processing message 0x7f8924095e28
29-09-2014 08:46:01.539 UTC Debug stack.cpp:203: Request latency = 6651us
29-09-2014 08:46:01.541 UTC Verbose httpstack.cpp:259: Process request for 
URL /authentication-timeout, args (null)
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\20f6cb34339810b4 hashes to vbucket 31 via hash 
0x834b2a1f
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:304: 1 read replicas 
for key av\\0000001...@example.com\20f6cb34339810b4
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:337: Attempt to read 
from replica 0 (connection 0x7f8930010970)
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:343: Fetch result
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:373: Read for 
av\\0000001...@example.com\20f6cb34339810b4 on replica 0 returned NOTFOUND
29-09-2014 08:46:01.541 UTC Debug memcachedstore.cpp:413: At least one 
replica returned not found, so return NOT_FOUND
29-09-2014 08:46:01.541 UTC Warning handlers.cpp:573: Could not find AV for 
0000001...@example.com:20f6cb34339810b4 when checking authentication timeout
29-09-2014 08:46:01.541 UTC Debug handlers.cpp:167: Unable to handle 
callback from Chronos
29-09-2014 08:46:01.541 UTC Verbose httpstack.cpp:68: Sending response 500 
to request for URL /authentication-timeout, args (null)
29-09-2014 08:46:01.550 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg REGISTER/cseq=3 (rdata0x7f8924026818)
29-09-2014 08:46:01.550 UTC Verbose stack.cpp:232: RX 1094 bytes Request msg 
REGISTER/cseq=3 (rdata0x7f8924026818) from TCP 192.168.20.68:38457:
--start msg--

REGISTER sip:example.com SIP/2.0
Path: sip:CXGoU0eTWN@192.168.20.68:5058;transport=TCP;lr;ob
Via: SIP/2.0/TCP 
192.168.20.68:38457;rport;branch=z9hG4bKPjj1VhM1fm-CSapcMiua.WV7Jq9UmhH4qa
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-b49d5e7d2feccc32-1---d8754z-
Max-Forwards: 69
Contact: <sip:0000001005@192.168.20.50:5060;rinstance=8a6c503517a7e66d>
To: "1005" <sip:0000001...@example.com>
From: "1005" <sip:0000001...@example.com>;tag=1010416b
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
CSeq: 3 REGISTER
Expires: 3600
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, 
INFO
User-Agent: X-Lite release 4.5.5  stamp 71236
Authorization: Digest username="0000001...@example.com", 
realm="example.com", nonce="20f6cb34339810b4", uri="sip:example.com", 
response="b8d4d81c116c8fbce5e9c5dd39869edd", algorithm=MD5, 
cnonce="41134ec7947e98cf255bdb50a16df389", opaque="38e5df0d3d3d7da1", 
qop=auth, nc=00000001
Session-Expires: 600
Route: <sip:192.168.20.68:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
29-09-2014 08:46:01.550 UTC Debug stack.cpp:425: Queuing cloned received 
message 0x7f8924095e28 for worker threads
29-09-2014 08:46:01.550 UTC Debug stack.cpp:195: Worker thread dequeue 
message 0x7f8924095e28
29-09-2014 08:46:01.550 UTC Debug pjsip: sip_endpoint.c Distributing rdata 
to modules: Request msg REGISTER/cseq=3 (rdata0x7f8924095e28)
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:175: Set up new view 1 
for thread
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:184: Setting up server 
0 for connection 0x1ab95d0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS)
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:186: Set up connection 
0x1a0eab0 to server 192.168.20.68:11211
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:228: Setting server to 
IP address 192.168.20.68 port 11211
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\20f6cb34339810b4 hashes to vbucket 31 via hash 
0x834b2a1f
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:304: 1 read replicas 
for key av\\0000001...@example.com\20f6cb34339810b4
29-09-2014 08:46:01.550 UTC Debug memcachedstore.cpp:337: Attempt to read 
from replica 0 (connection 0x1a0eab0)
29-09-2014 08:46:01.551 UTC Debug memcachedstore.cpp:343: Fetch result
29-09-2014 08:46:01.551 UTC Debug memcachedstore.cpp:373: Read for 
av\\0000001...@example.com\20f6cb34339810b4 on replica 0 returned NOTFOUND
29-09-2014 08:46:01.551 UTC Debug memcachedstore.cpp:413: At least one 
replica returned not found, so return NOT_FOUND
29-09-2014 08:46:01.551 UTC Debug authentication.cpp:531: Verify 
authentication information in request
29-09-2014 08:46:01.551 UTC Warning authentication.cpp:205: Received an 
authentication request for 0000001...@example.com with nonce 
20f6cb34339810b4, but no matching AV found
29-09-2014 08:46:01.551 UTC Debug acr.cpp:48: Created ACR (0x1b00d70)
29-09-2014 08:46:01.551 UTC Debug authentication.cpp:650: No authentication 
information in request or stale nonce, so reject with challenge
29-09-2014 08:46:01.551 UTC Debug pjsip:       endpoint Response msg 
401/REGISTER/cseq=3 (tdta0x1b00d90) created
29-09-2014 08:46:01.551 UTC Debug pjutils.cpp:432: Private identity from 
authorization header = 0000001...@example.com
29-09-2014 08:46:01.551 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x1b01e20
29-09-2014 08:46:01.553 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 8888, family 2
29-09-2014 08:46:01.553 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.553 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.553 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : 
http://192.168.20.68:8888/impi/0000001005%40example.com/av?impu=sip%3A0000001005%40example.com
 
(trying 192.168.20.68) on new connection
29-09-2014 08:46:01.557 UTC Debug httpconnection.cpp:545: Received HTTP 
response : 
{"digest":{"ha1":"78b9f6376646ef8411472d40530519e0","realm":"example.com","qop":"auth"}}
29-09-2014 08:46:01.558 UTC Debug statistic.cpp:103: Send new value for 
statistic connected_homesteads, size 2
29-09-2014 08:46:01.558 UTC Debug zmq_lvc.cpp:167: Update to 
connected_homesteads statistic
29-09-2014 08:46:01.558 UTC Debug zmq_lvc.cpp:250: Clearing message cache 
for 0x7f893c009dc0
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:147: Digest specified
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:309: Valid AV - 
generate challenge
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:315: Create 
WWW-Authenticate header
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:361: Add Digest 
information
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:390: Write AV to store
29-09-2014 08:46:01.558 UTC Debug avstore.cpp:66: Set AV for 
0000001...@example.com\16fd02d5209472a5
{"branch":"z9hG4bKPjj1VhM1fm-CSapcMiua.WV7Jq9UmhH4qa","digest":{"ha1":"78b9f6376646ef8411472d40530519e0","qop":"auth","realm":"example.com"}}

29-09-2014 08:46:01.558 UTC Debug memcachedstore.cpp:449: Writing 142 bytes 
to table av key 0000001...@example.com\16fd02d5209472a5, CAS = 0, expiry = 
40
29-09-2014 08:46:01.558 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\16fd02d5209472a5 hashes to vbucket 102 via hash 
0x7bdc1666
29-09-2014 08:46:01.558 UTC Debug memcachedstore.cpp:468: 1 write replicas 
for key av\\0000001...@example.com\16fd02d5209472a5
29-09-2014 08:46:01.558 UTC Debug memcachedstore.cpp:506: Attempt 
conditional write to replica 0 (connection 0x1a0eab0), CAS = 0
29-09-2014 08:46:01.558 UTC Debug memcachedstore.cpp:542: Conditional write 
succeeded to replica 0
29-09-2014 08:46:01.558 UTC Debug authentication.cpp:400: Sending {"impi": 
"0000001...@example.com", "impu": "sip:0000001...@example.com", "nonce": 
"16fd02d5209472a5"} to Chronos to set AV timer
29-09-2014 08:46:01.558 UTC Debug httpconnection.cpp:176: Allocated CURL 
handle 0x1b3aff0
29-09-2014 08:46:01.559 UTC Debug httpresolver.cpp:70: HttpResolver::resolve 
for host 192.168.20.68, port 7253, family 2
29-09-2014 08:46:01.559 UTC Debug baseresolver.cpp:480: Attempt to parse 
192.168.20.68 as IP address
29-09-2014 08:46:01.559 UTC Debug httpresolver.cpp:78: Target is an IP 
address
29-09-2014 08:46:01.559 UTC Debug httpconnection.cpp:532: Sending HTTP 
request : http://192.168.20.68:7253/timers (trying 192.168.20.68) on new 
connection
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
http/1.1200ok with value
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
location with value /timers/000aa3af400000088000000800600500
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
date with value Mon,29Sep201408:46:01GMT
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
content-length with value 0
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
content-type with value text/html;charset=ISO-8859-1
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:825: Received header 
with value
29-09-2014 08:46:01.560 UTC Debug httpconnection.cpp:545: Received HTTP 
response :
29-09-2014 08:46:01.560 UTC Verbose stack.cpp:248: TX 630 bytes Response msg 
401/REGISTER/cseq=3 (tdta0x1b00d90) to TCP 192.168.20.68:38457:
--start msg--

SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 
192.168.20.68:38457;rport=38457;received=192.168.20.68;branch=z9hG4bKPjj1VhM1fm-CSapcMiua.WV7Jq9UmhH4qa
Via: SIP/2.0/UDP 
192.168.20.50:5060;rport=5060;received=192.168.20.50;branch=z9hG4bK-d8754z-b49d5e7d2feccc32-1---d8754z-
Call-ID: YTg4NTdjYmVmNDE3NjZkMmUyNGExNzQ4MmRiODMwZDc
From: "1005" <sip:0000001...@example.com>;tag=1010416b
To: "1005" 
<sip:0000001...@example.com>;tag=z9hG4bKPjj1VhM1fm-CSapcMiua.WV7Jq9UmhH4qa
CSeq: 3 REGISTER
WWW-Authenticate: Digest 
realm="example.com",nonce="16fd02d5209472a5",opaque="358037802bee54a4",algorithm=MD5,qop="auth"
Content-Length:  0


--end msg--
29-09-2014 08:46:01.560 UTC Debug pjsip:  tdta0x1b00d90 Destroying txdata 
Response msg 401/REGISTER/cseq=3 (tdta0x1b00d90)
29-09-2014 08:46:01.560 UTC Debug acr.cpp:82: Sending Null ACR (0x1b00d70)
29-09-2014 08:46:01.560 UTC Debug acr.cpp:53: Destroyed ACR (0x1b00d70)
29-09-2014 08:46:01.560 UTC Debug stack.cpp:197: Worker thread completed 
processing message 0x7f8924095e28
29-09-2014 08:46:01.560 UTC Debug stack.cpp:203: Request latency = 10026us
29-09-2014 08:46:01.563 UTC Verbose httpstack.cpp:259: Process request for 
URL /authentication-timeout, args (null)
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:260: Key 
av\\0000001...@example.com\16fd02d5209472a5 hashes to vbucket 102 via hash 
0x7bdc1666
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:304: 1 read replicas 
for key av\\0000001...@example.com\16fd02d5209472a5
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:337: Attempt to read 
from replica 0 (connection 0x7f8930010970)
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:343: Fetch result
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:373: Read for 
av\\0000001...@example.com\16fd02d5209472a5 on replica 0 returned NOTFOUND
29-09-2014 08:46:01.563 UTC Debug memcachedstore.cpp:413: At least one 
replica returned not found, so return NOT_FOUND
29-09-2014 08:46:01.563 UTC Warning handlers.cpp:573: Could not find AV for 
0000001...@example.com:16fd02d5209472a5 when checking authentication timeout
29-09-2014 08:46:01.563 UTC Debug handlers.cpp:167: Unable to handle 
callback from Chronos
29-09-2014 08:46:01.563 UTC Verbose httpstack.cpp:68: Sending response 500 
to request for URL /authentication-timeout, args (null)


rgds
Simon
-----Original Message----- 
From: Eleanor Merry
Sent: Friday, September 26, 2014 2:50 PM
To: simon connolly ; clearwater@lists.projectclearwater.org
Subject: RE: [Clearwater] SIP Registration Failure: 403 Forbidden

Hi Simon,

Your X-Lite configuration looks correct. Can you please send me the debug 
logs from Sprout from an attempted register? You can turn on debug logging 
by creating/editing the file /etc/clearwater/user_settings, adding 
log_level=5 and then restarting Sprout (service sprout stop - it's 
automatically restarted by monit). The Sprout logs are output in 
/var/log/sprout/*.

Also, what version of Zoiper are you using, and on what system?

Thanks,

Ellie

-----Original Message-----
From: clearwater-boun...@lists.projectclearwater.org 
[mailto:clearwater-boun...@lists.projectclearwater.org] On Behalf Of simon 
connolly
Sent: 25 September 2014 15:48
To: clearwater@lists.projectclearwater.org
Subject: Re: [Clearwater] SIP Registration Failure: 403 Forbidden

Hi Ellie

thanks for reply

in the log I sent for sprout below I was using Zoiper softphone (which is 
recomended on clearwater website) but there doesnt seem to be a field to set 
authorization name, there are only 3 fields it allows you to set, which I 
set as below

user / user host : 0000001...@example.com
password: <password>
Domain / Outbound proxy: 192.168.20.68

I have now tried using XLite which does have a field to set auth name, Ive 
set fields as below:-

User ID: 0000001005
Domain : example.com
Password: <password>
Display name: 1005
Auth Name: 0000001...@example.com


I tried again and this time I get 401 Unauthorised, but log is different, 
shows the correct format for the private identity i think

24-09-2014 08:29:43.360 UTC Warning authentication.cpp:205:
Received24-09-2014 17:31:56.657 UTC Warning authentication.cpp:205: Received 
an authentication request for 0000001...@example.com with nonce 
7883849902ac3e63, but no matching AV found
24-09-2014 17:31:56.670 UTC Warning authentication.cpp:205: Received an 
authentication request for 0000001...@example.com with nonce 
734410286b986924, but no matching AV found


what can be the reason for failed auth ?

thanks
Simon


-----Original Message-----
From: Eleanor Merry
Sent: Wednesday, September 24, 2014 6:14 PM
To: simon connolly ; clearwater@lists.projectclearwater.org
Subject: RE: [Clearwater] SIP Registration Failure: 403 Forbidden

Hi Simon,

You're right - the create_numbers script is used to tell Ellis which numbers 
are available for provisioning - it doesn't actually create any numbers on 
Homer/Homestead itself.

Looking at the diagnostics, it looks like you've got three provisioned users 
(1001, 1008 and 1005), and 7 more numbers available for provisioning. For 
each provisioned number, the public identity is sip:0000001...@example.com 
and the private identity is 0000001...@example.com

When you register, you need to configure your client so that authentication 
name matches the private identity - it looks from the logs that you're using 
0000001000x. What softphone are you using? Can you please try with 
00000010...@example.com instead?

Hope this helps,

Ellie

-----Original Message-----
From: clearwater-boun...@lists.projectclearwater.org
[mailto:clearwater-boun...@lists.projectclearwater.org] On Behalf Of simon 
connolly
Sent: 24 September 2014 11:52
To: clearwater@lists.projectclearwater.org
Subject: [Clearwater] SIP Registration Failure: 403 Forbidden

Hi

I’ve recently installed the all-in-one version of clearwater and I am having 
trouble registering a user. When I installed the OVF there were 1000 users 
created automatically in Ellis database, but only a handful (about 50) of 
these 1000 were in other databases ie homer, homestead. I thought this might 
be due to some installation issue.

To better understand how clearwater is working I decided to delete all the 
subscribers from Ellis and recreate just 10 (1000-1009) using the 
‘create_numbers.py’ scipt, as I wanted to see if deleting / creating users 
in Ellis would propagate through to other databases, but I found this wasn’t 
the case.

After search on internet I found info that the ‘create_numbers.py’ script 
doesn't actually create numbers on Homestead, it just provisions a pool of 
numbers on Ellis that Ellis can then select from during real number creation’, 
so now i’m confused how users are created in other databases...should this 
be done manually or is there some config issue which is stopping Ellis 
informing other databases about new users ?

below are the 10 users I created

mysql> select * from numbers;
+--------------------------------------+----------------------------+----------+------------+------+
| number_id                            | number                     |
owner_id | gab_listed | pstn |
+--------------------------------------+----------------------------+----------+------------+------+
| 008ccc4a-1972-4510-9a3e-bcea60983ec4 | sip:0000001...@example.com | NULL
|          1 |    0 |
| 070680ec-9934-4c21-8f84-fa3538e735a9 | sip:0000001...@example.com | NULL
|          1 |    0 |
| 09218e54-4427-472f-bc6a-b00eac4464ed | sip:0000001...@example.com | NULL
|          1 |    0 |
| 43cb9b77-7581-41bb-b1c8-1bc6aac4d9ba | sip:0000001...@example.com | NULL
|          1 |    0 |
| 693e3271-525b-4002-9683-3e29816db695 | sip:0000001...@example.com | NULL
|          1 |    0 |
| 6f35ccbf-3228-4d33-942b-147604a027fb | sip:0000001...@example.com | NULL
|          1 |    0 |
| 96cf89c3-8f61-4ddc-a9fc-1ffcf0e00c4b | sip:0000001...@example.com | NULL
|          1 |    0 |
| a2800cf0-10ef-4d65-ac3c-89e634c5617c | sip:0000001...@example.com | NULL
|          1 |    0 |
| aef13d75-159f-4c4a-8d4f-420b539e4b93 | sip:0000001...@example.com | NULL
|          1 |    0 |
| af3d3ca7-49aa-4b34-8750-d87a695a29d8 | sip:0000001...@example.com | NULL
|          1 |    0 |
+--------------------------------------+----------------------------+----------+------------+------+

using the web interface I generated 3 private identities (1001, 1008, 1005), 
which worked and I got a password for each.

Can see in mysql that owner-id field is now filled, so this part is working 
fine


mysql> select * from numbers;
+--------------------------------------+----------------------------+--------------------------------------+------------+------+
| number_id                            | number                     |
owner_id                             | gab_listed | pstn |
+--------------------------------------+----------------------------+--------------------------------------+------------+------+
| 008ccc4a-1972-4510-9a3e-bcea60983ec4 | sip:0000001...@example.com |
ad2dec28-eadc-4501-87d6-c74c2ed28676 |          1 |    0 |
| 070680ec-9934-4c21-8f84-fa3538e735a9 | sip:0000001...@example.com |
ad2dec28-eadc-4501-87d6-c74c2ed28676 |          1 |    0 |
| 09218e54-4427-472f-bc6a-b00eac4464ed | sip:0000001...@example.com |
ad2dec28-eadc-4501-87d6-c74c2ed28676 |          1 |    0 |
| 43cb9b77-7581-41bb-b1c8-1bc6aac4d9ba | sip:0000001...@example.com | NULL
|          1 |    0 |
| 693e3271-525b-4002-9683-3e29816db695 | sip:0000001...@example.com | NULL
|          1 |    0 |
| 6f35ccbf-3228-4d33-942b-147604a027fb | sip:0000001...@example.com | NULL
|          1 |    0 |
| 96cf89c3-8f61-4ddc-a9fc-1ffcf0e00c4b | sip:0000001...@example.com | NULL
|          1 |    0 |
| a2800cf0-10ef-4d65-ac3c-89e634c5617c | sip:0000001...@example.com | NULL
|          1 |    0 |
| aef13d75-159f-4c4a-8d4f-420b539e4b93 | sip:0000001...@example.com | NULL
|          1 |    0 |
| af3d3ca7-49aa-4b34-8750-d87a695a29d8 | sip:0000001...@example.com | NULL
|          1 |    0 |
+--------------------------------------+----------------------------+--------------------------------------+------------+------+


I then tried to register with softphone, clearwater first sends back 401 
Unauthorised (so it recognises the user ), softphone then replies with sip 
register which includes auth parameters this time, but the clearwater sends 
back 403 forbidden. In sprout log i see errors below which seem to point at 
impi and impu tables in homestead_cache database, that they cant find 
matching record


24-09-2014 08:29:43.360 UTC Warning authentication.cpp:205: Received an 
authentication request for 0000001008 with nonce 5073304c580c6b04, but no 
matching AV found
24-09-2014 08:29:43.362 UTC Error httpconnection.cpp:561:
http://192.168.20.68:8888/impi/0000001008/av?impu=sip%3A0000001008%40example.com
failed at server 192.168.20.68 : HTTP response code said error (22 404) :
fatal
24-09-2014 08:29:43.362 UTC Error httpconnection.cpp:659: cURL failure with 
cURL error code 22 (see man 3 libcurl-errors) and HTTP error code 404
24-09-2014 08:29:43.362 UTC Error hssconnection.cpp:144: Failed to get 
Authentication Vector for 0000001008


this makes sense as there are no entries for the 10 users I created in 
either of these 2 tables


please advise

many thanks

Simon














_______________________________________________
Clearwater mailing list
Clearwater@lists.projectclearwater.org
http://lists.projectclearwater.org/listinfo/clearwater

_______________________________________________
Clearwater mailing list
Clearwater@lists.projectclearwater.org
http://lists.projectclearwater.org/listinfo/clearwater 

_______________________________________________
Clearwater mailing list
Clearwater@lists.projectclearwater.org
http://lists.projectclearwater.org/listinfo/clearwater