[Project Clearwater] user authentication issue error 404 on homestead

[masood.tahir696]

Hi all,

I have deployed the vIMS (manual installation) using the heat templates. I have 
created the users in homestead using the bulk create script. the users are 
successfully created in the homestead.

when I try to register the users it gives an error 404 I have  tried both 
x-lite and zoiper to register and also verified the authentication I.D




I have set the log level=5 in user_settings and the debug logs are attached.






Any guidance would be most appreciated.

Regards,

 Tahir
26-04-2016 07:15:55.507 UTC Verbose httpstack.cpp:293: Process request for URL 
/impi/2010000006%40example.com/av, args impu=sip%3A2010000006%40example.com
26-04-2016 07:15:55.507 UTC Debug handlers.cpp:148: Parsed HTTP request: 
private ID 2010000...@example.com, public ID sip:2010000...@example.com, scheme 
Unknown, authorization
26-04-2016 07:15:55.507 UTC Debug handlers.cpp:174: Querying cache for 
authentication vector for 2010000...@example.com/sip:2010000...@example.com
26-04-2016 07:15:55.507 UTC Debug cassandra_store.cpp:284: Getting thread-local 
Client
26-04-2016 07:15:55.507 UTC Debug cassandra_store.cpp:289: No thread-local 
Client - creating one
26-04-2016 07:15:55.508 UTC Debug cache.cpp:670: Looking for authentication 
vector for 2010000...@example.com
26-04-2016 07:15:55.508 UTC Debug cache.cpp:682: Checking public ID 
sip:2010000...@example.com
26-04-2016 07:15:55.508 UTC Debug cache.cpp:692: Issuing cache query
26-04-2016 07:15:55.509 UTC Debug cassandra_store.cpp:724: Failed TWO read for 
get_columns. Try ONE
26-04-2016 07:15:55.511 UTC Debug communicationmonitor.cpp:82: Checking 
communication changes - successful attempts 2, failures 0
26-04-2016 07:15:55.511 UTC Debug handlers.cpp:194: Got authentication vector 
with digest cf2e8e82550b221743c55ed88b1f8a54 from cache
26-04-2016 07:15:55.511 UTC Verbose httpstack.cpp:69: Sending response 200 to 
request for URL /impi/2010000006%40example.com/av, args 
impu=sip%3A2010000006%40example.com
26-04-2016 07:15:55.861 UTC Verbose httpstack.cpp:293: Process request for URL 
/impu/sip%3Aexample.com/reg-data, args (null)
26-04-2016 07:15:55.861 UTC Debug handlers.cpp:1054: Parsed HTTP request: 
private ID , public ID sip:example.com
26-04-2016 07:15:55.861 UTC Debug handlers.cpp:998: Determining request type 
from '{"reqtype": "call"}'
26-04-2016 07:15:55.861 UTC Debug handlers.cpp:1042: New value of _type is 2
26-04-2016 07:15:55.861 UTC Debug handlers.cpp:1092: Try to find IMS 
Subscription information in the cache
26-04-2016 07:15:55.861 UTC Debug cassandra_store.cpp:284: Getting thread-local 
Client
26-04-2016 07:15:55.861 UTC Debug cassandra_store.cpp:289: No thread-local 
Client - creating one
26-04-2016 07:15:55.862 UTC Debug cassandra_store.cpp:129: Generated Cassandra 
timestamp 1461654955862777
26-04-2016 07:15:55.862 UTC Debug cache.cpp:347: Issuing get for key 
sip:example.com
26-04-2016 07:15:55.863 UTC Debug cassandra_store.cpp:755: Failed TWO read for 
get_row. Try ONE
26-04-2016 07:15:55.865 UTC Debug handlers.cpp:1121: Got IMS subscription from 
cache
26-04-2016 07:15:55.865 UTC Debug handlers.cpp:1137: TTL for this database 
record is 0, IMS Subscription XML is empty, registration state is 
NOT_REGISTERED, and the charging addresses are empty
26-04-2016 07:15:55.865 UTC Debug handlers.cpp:1352: Handling call
26-04-2016 07:15:55.865 UTC Verbose httpstack.cpp:69: Sending response 404 to 
request for URL /impu/sip%3Aexample.com/reg-data, args (null)
26-04-2016 07:16:04.629 UTC Verbose httpstack.cpp:293: Process request for URL 
/ping, args (null)
26-04-2016 07:16:04.629 UTC Verbose httpstack.cpp:69: Sending response 200 to 
request for URL /ping, args (null)

cqlsh> use homestead_cache;
cqlsh:homestead_cache> SELECT * from impi;

 private_id             | digest_ha1                       | digest_qop | 
digest_realm
------------------------+----------------------------------+------------+--------------
 2010000...@example.com | f1d6dcadb52bede5fb74fbc1c720bc0d |       null |  
example.com
 2010000...@example.com | 9f5bef62c778205357ab0a0d37e33a6b |       null |  
example.com
 2010000...@example.com | f6c1b2081138c0a0fd1d17f526f27a70 |       null |  
example.com
 2010000...@example.com | 9e4a70e334517fb0b706e552079f3aa5 |       null |  
example.com
 2010000...@example.com | db7349ed2ec6ea682a608e9a2e4dcbaa |       null |  
example.com
 2010000...@example.com | be73561a3c7f38ee344cc1c522ba5f0d |       null |  
example.com
 2010000...@example.com | f6e9bfa09b978e452828ffe3fa367ea4 |       null |  
example.com
 2010000...@example.com | f9807d6b35fc1da00a567ee47aeb8c52 |       null |  
example.com
 2010000...@example.com | 381a204d0cc11e455b5f4ddc5fb03937 |       null |  
example.com
 2010000...@example.com | cc1ed479a130270f053e935ae05d7de6 |       null |  
example.com
 2010000...@example.com | 7fac36438302a588c0474c619eef532b |       null |  
example.com
 2010000...@example.com | ef2927766881f97deb7074a1dc5c173f |       null |  
example.com
 2010000...@example.com | f4a23123c9525426189620d7fcec11ee |       null |  
example.com
 2010000...@example.com | f2579be84d4276c196d15c7d5dd78250 |       null |  
example.com
 2010000...@example.com | 50869dc040b2611bf06d698ae64a0b8a |       null |  
example.com
 2010000...@example.com | b9d058a797d4a78d9a024aa54e7a0193 |       null |  
example.com
 2010000...@example.com | f6b153b0e1f5e474901568dc23cee8fb |       null |  
example.com
 2010000...@example.com | da5bfbd697d604145ccc98a25fbf1bc8 |       null |  
example.com
 2010000...@example.com | 8fe75313e15a856651efa82fefa515ca |       null |  
example.com
 2010000...@example.com | 6c1ee0d537cc25a66261d6df8ad11430 |       null |  
example.com
 2010000...@example.com | 0aff143a2f89d3c4f5d8b3f93aee2772 |       null |  
example.com
 2010000...@example.com | 14c316060b6dab94e57002f0cb5aff09 |       null |  
example.com
 2010000...@example.com | 61c72c81c6d88f618b88beb7b10b0f3a |       null |  
example.com
 2010000...@example.com | 54ee287a77fc06a9a5653220e25ce15f |       null |  
example.com
 2010000...@example.com | 205e4b8ab680d4e831f15c3557def69c |       null |  
example.com
 2010000...@example.com | 5e97c8634f88e8c973dbd125d1e36b8a |       null |  
example.com
 2010000...@example.com | f6e333e9e938a4f529ae45517dba87e4 |       null |  
example.com
 2010000...@example.com | 40e87ac7ff2390ae862c7c2cfbbaf3ac |       null |  
example.com
 2010000...@example.com | e488b1d1fd3d2ab8b8dd3be2fbc86218 |       null |  
example.com
 2010000...@example.com | f8e99835562c0c13be847a6efb5ff706 |       null |  
example.com
 2010000...@example.com | f2fb1130ce3ff09539aa6504952c6c04 |       null |  
example.com
 2010000...@example.com | a054e5d98c8c33cd5551c3b90c4b4b36 |       null |  
example.com
 2010000...@example.com | a1ee3da9c03535e104dd4cc6a80ba0b7 |       null |  
example.com
 2010000...@example.com | 1c7f312c82ae380284d24835b9bb27cb |       null |  
example.com
 2010000...@example.com | 44c3b32880040a5563908edd63d243dc |       null |  
example.com
 2010000...@example.com | 47f800201ac09dcb214c2a65a3843c86 |       null |  
example.com
 2010000...@example.com | 6bfcae70fe5a224a7c0832edfef79579 |       null |  
example.com
 2010000...@example.com | 421ae7307bd32ac2c93aa5090c7e8b59 |       null |  
example.com
 2010000...@example.com | 9e17e3c59ca5f1e702c8439d8a8139d1 |       null |  
example.com
 2010000...@example.com | 5797f89d4946d5fb0a9025ce499c3edb |       null |  
example.com
 2010000...@example.com | 4d75b5b01debfac8b063c84db63fabaf |       null |  
example.com
 2010000...@example.com | f82acb567ea96f83a8c5b7f8b1d6b1bd |       null |  
example.com
 2010000...@example.com | 265526d6927e639f4e11ded975dbf5eb |       null |  
example.com
 2010000...@example.com | cbd5f4c8a3e4410b9da5c5f83e6e61d7 |       null |  
example.com
 2010000...@example.com | 4810473e38a85a2cf8be45c3dae5f5fb |       null |  
example.com
 2010000...@example.com | 31b149924bd5d78f7954c162138a87a0 |       null |  
example.com
 2010000...@example.com | 6eca99b87b369c45e82880a1c71bd97d |       null |  
example.com
 2010000...@example.com | 71b583a49131accf545494f6bb872ef7 |       null |  
example.com
 2010000...@example.com | 2a9cc26b333284a8db922e41ada8b198 |       null |  
example.com
 2010000...@example.com | 11b4e408b1c2ab88ec5ae7196d5581bd |       null |  
example.com
 2010000...@example.com | 1706b2972bc9f6decf332e4f560e4575 |       null |  
example.com
 2010000...@example.com | 750c02a4d60d6be1993862b5e94dd6a1 |       null |  
example.com
 2010000...@example.com | 7fd922ae665452e22f270e49492492ec |       null |  
example.com
 2010000...@example.com | 67ed2824f93e197b40a5d4a491b49a08 |       null |  
example.com
 2010000...@example.com | 25c7e62991b671c41e02f8982a6a1895 |       null |  
example.com
 2010000...@example.com | 568c8ef0720b75181f39298f14f917b9 |       null |  
example.com
 2010000...@example.com | b62230cf728e937a964ff4324a28be70 |       null |  
example.com
 2010000...@example.com | 32e9a4c33e3fa1cbe83df8171a919961 |       null |  
example.com
 2010000...@example.com | d8a0364d469ca99a3b031c7c789e2f9b |       null |  
example.com
 2010000...@example.com | 6e600f24ca288f51426b20ad097fe72e |       null |  
example.com
 2010000...@example.com | e5aba16fc2da8ad97e09484a02827309 |       null |  
example.com
 2010000...@example.com | d5e7b88f4811967b62f52b34cb402405 |       null |  
example.com
 2010000...@example.com | b4322fb049a1977af46296f21584c3b4 |       null |  
example.com
 2010000...@example.com | d1f56e799ec8688a9a5ce8dbb8dbd630 |       null |  
example.com
 2010000...@example.com | 7d0a3270e0291cb624c0391cfd1998c3 |       null |  
example.com
 2010000...@example.com | 0cf0cae6c1e03efdfc2648c0c3b7f08e |       null |  
example.com
 2010000...@example.com | e894b5f1c93948241ac992df1b2a885a |       null |  
example.com
 2010000...@example.com | 14f358b992a7c9e5caa2b3d302b7cc1e |       null |  
example.com
 2010000...@example.com | 4a102c6a8ff6167c60de38353365a900 |       null |  
example.com
 2010000...@example.com | c12bf456e9f0ec9ae09426c786d6d18f |       null |  
example.com
 2010000...@example.com | 4c3c4c887f70260657001b7cef5d8c11 |       null |  
example.com
 2010000...@example.com | cf2e8e82550b221743c55ed88b1f8a54 |       null |  
example.com
 2010000...@example.com | 617b1ecc8588e087e1c6cb5ae444a83d |       null |  
example.com
 2010000...@example.com | 58b944189ed7476aa823c05e59fb1b30 |       null |  
example.com
 2010000...@example.com | d98042702e28d3e0144cdc21acfd3574 |       null |  
example.com

--start msg--

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


--end msg--
26-04-2016 07:15:49.465 UTC Debug uri_classifier.cpp:167: home domain: false, 
local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:49.465 UTC Debug uri_classifier.cpp:197: Classified URI as 3
26-04-2016 07:15:49.465 UTC Debug common_sip_processing.cpp:212: Skipping SAS 
logging for OPTIONS request
26-04-2016 07:15:49.465 UTC Debug thread_dispatcher.cpp:253: Queuing cloned 
received message 0x7f308409f268 for worker threads
26-04-2016 07:15:49.466 UTC Debug thread_dispatcher.cpp:149: Worker thread 
dequeue message 0x7f308409f268
26-04-2016 07:15:49.466 UTC Debug pjsip: sip_endpoint.c Distributing rdata to 
modules: Request msg OPTIONS/cseq=65309 (rdata0x7f308409f268)
26-04-2016 07:15:49.466 UTC Debug uri_classifier.cpp:167: home domain: false, 
local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:49.466 UTC Debug uri_classifier.cpp:197: Classified URI as 3
26-04-2016 07:15:49.466 UTC Debug pjsip:       endpoint Response msg 
200/OPTIONS/cseq=65309 (tdta0x7f30ec0137a0) created
26-04-2016 07:15:49.466 UTC Verbose common_sip_processing.cpp:136: TX 273 bytes 
Response msg 200/OPTIONS/cseq=65309 (tdta0x7f30ec0137a0) to TCP 
192.168.0.5:42154:
--start msg--

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


--end msg--
26-04-2016 07:15:49.466 UTC Debug common_sip_processing.cpp:254: Skipping SAS 
logging for OPTIONS response
26-04-2016 07:15:49.466 UTC Debug pjsip: tdta0x7f30ec01 Destroying txdata 
Response msg 200/OPTIONS/cseq=65309 (tdta0x7f30ec0137a0)
26-04-2016 07:15:49.466 UTC Debug thread_dispatcher.cpp:193: Worker thread 
completed processing message 0x7f308409f268
26-04-2016 07:15:49.466 UTC Debug thread_dispatcher.cpp:199: Request latency = 
557us
26-04-2016 07:15:49.511 UTC Verbose httpstack.cpp:293: Process request for URL 
/ping, args (null)
26-04-2016 07:15:49.511 UTC Verbose httpstack.cpp:69: Sending response 200 to 
request for URL /ping, args (null)
26-04-2016 07:15:50.466 UTC Verbose pjsip: tcps0x7f308409 TCP connection closed
26-04-2016 07:15:50.466 UTC Debug connection_tracker.cpp:91: Connection 
0x7f308409c568 has been destroyed
26-04-2016 07:15:50.466 UTC Verbose pjsip: tcps0x7f308409 TCP transport 
destroyed with reason 70016: End of file (PJ_EEOF)
26-04-2016 07:15:55.516 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg REGISTER/cseq=1 (rdata0x7f3084031710)
26-04-2016 07:15:55.516 UTC Verbose common_sip_processing.cpp:120: RX 838 bytes 
Request msg REGISTER/cseq=1 (rdata0x7f3084031710) from TCP 192.168.0.6:43546:
--start msg--

REGISTER sip:example.com SIP/2.0
Via: SIP/2.0/TCP 
192.168.0.6:43546;rport;branch=z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7
Path: <sip:7N8NRxC67H@192.168.0.6:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP 
10.204.67.13:64453;rport=64453;received=10.204.67.13;branch=z9hG4bK-524287-1---e4bd846009ee2652
Max-Forwards: 70
Contact: <sip:2010000006@10.204.67.13:64453;rinstance=1608df1e538dd29d>
To: "2010000006" <sip:2010000...@example.com>
From: "2010000006" <sip:2010000...@example.com>;tag=c40b1c7d
Call-ID: 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
CSeq: 1 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, 
MESSAGE
User-Agent: X-Lite release 4.9.3 stamp 79961
P-Visited-Network-ID: example.com
Route: <sip:sprout.example.com:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
26-04-2016 07:15:55.516 UTC Debug pjutils.cpp:1662: Logging SAS Call-ID marker, 
Call-ID 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
26-04-2016 07:15:55.516 UTC Debug thread_dispatcher.cpp:253: Queuing cloned 
received message 0x7f30840a7e48 for worker threads
26-04-2016 07:15:55.516 UTC Debug thread_dispatcher.cpp:149: Worker thread 
dequeue message 0x7f30840a7e48
26-04-2016 07:15:55.516 UTC Debug pjsip: sip_endpoint.c Distributing rdata to 
modules: Request msg REGISTER/cseq=1 (rdata0x7f30840a7e48)
26-04-2016 07:15:55.516 UTC Debug uri_classifier.cpp:167: home domain: true, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.516 UTC Debug uri_classifier.cpp:197: Classified URI as 4
26-04-2016 07:15:55.516 UTC Debug authentication.cpp:775: Authentication module 
invoked
26-04-2016 07:15:55.517 UTC Debug authentication.cpp:789: Request needs 
authentication
26-04-2016 07:15:55.517 UTC Debug acr.cpp:1765: Create RalfACR for node type 
S-CSCF with role Originating
26-04-2016 07:15:55.517 UTC Debug acr.cpp:49: Created ACR (0x2031d60)
26-04-2016 07:15:55.517 UTC Debug acr.cpp:177: Created S-CSCF Ralf ACR
26-04-2016 07:15:55.517 UTC Debug acr.cpp:216: Set record type for P/S-CSCF
26-04-2016 07:15:55.517 UTC Debug acr.cpp:224: Non-dialog message => 
EVENT_RECORD
26-04-2016 07:15:55.517 UTC Debug acr.cpp:1493: Stored 0 subscription 
identifiers
26-04-2016 07:15:55.517 UTC Debug authentication.cpp:1091: No authentication 
information in request or stale nonce, so reject with challenge
26-04-2016 07:15:55.517 UTC Debug pjsip:       endpoint Response msg 
401/REGISTER/cseq=1 (tdta0x2031fb0) created
26-04-2016 07:15:55.517 UTC Debug pjutils.cpp:423: Private identity defaulted 
from public identity = 2010000...@example.com
26-04-2016 07:15:55.518 UTC Debug httpconnection.cpp:183: Allocated CURL handle 
0x2033240
26-04-2016 07:15:55.519 UTC Debug httpresolver.cpp:71: HttpResolver::resolve 
for host hs.example.com, port 8888, family 2
26-04-2016 07:15:55.519 UTC Debug baseresolver.cpp:513: Attempt to parse 
hs.example.com as IP address
26-04-2016 07:15:55.519 UTC Verbose dnscachedresolver.cpp:240: Check cache for 
hs.example.com type 1
26-04-2016 07:15:55.519 UTC Debug dnscachedresolver.cpp:246: No entry found in 
cache
26-04-2016 07:15:55.519 UTC Debug dnscachedresolver.cpp:249: Create cache entry 
pending query
26-04-2016 07:15:55.520 UTC Debug dnscachedresolver.cpp:282: Create and execute 
DNS query transaction
26-04-2016 07:15:55.520 UTC Debug dnscachedresolver.cpp:294: Wait for query 
responses
26-04-2016 07:15:55.522 UTC Debug dnscachedresolver.cpp:435: Received DNS 
response for hs.example.com type A
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:90: Parsing DNS message
000000: 2e2e8580 00010001 00010001 02687307 6578616d 706c6503 636f6d00 00010001 
   .... .... .... .hs. exam ple. com. ....
000020: c00c0001 00010000 001e0004 c0a80007 c00f0002 00010000 0e100005 026e73c0 
   .... .... .... .... .... .... .... .ns.
000040: 0fc03c00 01000100 000e1000 04c0a800 01                                  
   ..<. .... .... .... .

26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:95: Parsing header at offset 0x0
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:98: 1 questions, 1 answers, 1 
authorities, 1 additional records
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:103: Parsing question 1 at 
offset 0xc
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:229: Parsed domain name = 
hs.example.com, encoded length = 16
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:112: Parsing answer 1 at offset 
0x20
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:229: Parsed domain name = 
hs.example.com, encoded length = 2
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:282: Resource Record 
NAME=hs.example.com TYPE=A CLASS=IN TTL=30 RDLENGTH=4
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:287: Parse A record RDATA
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:121: Parsing NS record 1 at 
offset 0x30
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:229: Parsed domain name = 
example.com, encoded length = 2
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:282: Resource Record 
NAME=example.com TYPE=NS CLASS=IN TTL=3600 RDLENGTH=5
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:130: Parsing additional record 
1 at offset 0x41
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:229: Parsed domain name = 
ns.example.com, encoded length = 2
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:282: Resource Record 
NAME=ns.example.com TYPE=A CLASS=IN TTL=3600 RDLENGTH=4
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:287: Parse A record RDATA
26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:142: Answer records
hs.example.com          30      IN      A       192.168.0.7

26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:143: Authority records
example.com             3600    IN      NS

26-04-2016 07:15:55.523 UTC Debug dnsparser.cpp:144: Additional records
ns.example.com          3600    IN      A       192.168.0.1

26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:704: Adding record to 
cache entry, TTL=30, expiry=1461654985
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:708: Update cache entry 
expiry to 1461654985
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:704: Adding record to 
cache entry, TTL=3600, expiry=1461658555
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:708: Update cache entry 
expiry to 1461658555
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:650: Adding 
ns.example.com to cache expiry list with deletion time of 1461658855
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:650: Adding 
hs.example.com to cache expiry list with deletion time of 1461655285
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:298: Received all query 
responses
26-04-2016 07:15:55.523 UTC Debug dnscachedresolver.cpp:326: Pulling 1 records 
from cache for hs.example.com A
26-04-2016 07:15:55.523 UTC Debug baseresolver.cpp:361: Found 1 A/AAAA records, 
randomizing
26-04-2016 07:15:55.523 UTC Debug baseresolver.cpp:503: 192.168.0.7:8888 
transport 6 is not blacklisted
26-04-2016 07:15:55.523 UTC Debug baseresolver.cpp:382: Added a server, now 
have 1 of 5
26-04-2016 07:15:55.523 UTC Debug baseresolver.cpp:420: Adding 0 servers from 
blacklist
26-04-2016 07:15:55.523 UTC Debug httpconnection.cpp:623: Sending HTTP request 
: 
http://hs.example.com:8888/impi/2010000006%40example.com/av?impu=sip%3A2010000006%40example.com
 (trying 192.168.0.7) on new connection
26-04-2016 07:15:55.531 UTC Debug httpconnection.cpp:638: Received HTTP 
response: status=200, 
doc={"digest":{"ha1":"cf2e8e82550b221743c55ed88b1f8a54","realm":"example.com","qop":"auth"}}
26-04-2016 07:15:55.531 UTC Debug communicationmonitor.cpp:82: Checking 
communication changes - successful attempts 1, failures 0
26-04-2016 07:15:55.531 UTC Debug alarm.cpp:465: AlarmReqAgent: servicing 
request queue
26-04-2016 07:15:55.531 UTC Status alarm.cpp:72: sprout issued 1001.1 alarm
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:197: Verifying AV: 
{"digest":{"ha1":"cf2e8e82550b221743c55ed88b1f8a54","realm":"example.com","qop":"auth"}}
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:224: Digest specified
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:386: Valid AV - generate 
challenge
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:395: Create 
WWW-Authenticate header
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:478: Add Digest information
26-04-2016 07:15:55.531 UTC Debug authentication.cpp:533: Write authentication 
challenge to IMPI store
26-04-2016 07:15:55.531 UTC Debug memcachedstore.cpp:195: Key 
impi\\2010000...@example.com hashes to vbucket 55 via hash 0xcc98f437
26-04-2016 07:15:55.531 UTC Debug memcachedstore.cpp:236: Set up new view 1 for 
thread
26-04-2016 07:15:55.531 UTC Debug memcachedstore.cpp:243: Setting up server 0 
for connection 0x207dce0 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --POLL-TIMEOUT=250 
--BINARY-PROTOCOL)
26-04-2016 07:15:55.531 UTC Debug memcachedstore.cpp:245: Set up connection 
0x2098e60 to server 192.168.0.5:11211
26-04-2016 07:15:55.531 UTC Debug memcachedstore.cpp:256: Setting server to IP 
address 192.168.0.5 port 11211
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:367: 1 read replicas for 
key impi\\2010000...@example.com
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:402: Attempt to read from 
replica 0 (connection 0x2098e60)
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:780: Fetch result
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:418: Read for 
impi\\2010000...@example.com on replica 0 returned NOTFOUND
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:492: At least one replica 
returned not found, so return NOT_FOUND
26-04-2016 07:15:55.532 UTC Debug communicationmonitor.cpp:82: Checking 
communication changes - successful attempts 1, failures 0
26-04-2016 07:15:55.532 UTC Status alarm.cpp:72: sprout issued 1002.1 alarm
26-04-2016 07:15:55.532 UTC Debug impistore.cpp:648: Storing IMPI for 
2010000...@example.com
{"authChallenges":[{"type":"digest","nonce":"68f9ca7502dd8cd6","nc":1,"expires":1461654995,"correlator":"z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7","realm":"example.com","qop":"auth","ha1":"cf2e8e82550b221743c55ed88b1f8a54"}]}
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:542: Writing 226 bytes to 
table impi key 2010000...@example.com, CAS = 0, expiry = 40
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:195: Key 
impi\\2010000...@example.com hashes to vbucket 55 via hash 0xcc98f437
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:562: 1 write replicas for 
key impi\\2010000...@example.com
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:616: Attempt conditional 
write to vbucket 55 on replica 0 (connection 0x2098e60), CAS = 0, expiry = 40
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:816: Attempting to add 
data for key impi\\2010000...@example.com
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:826: Attempting memcached 
ADD command
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:916: ADD/CAS returned rc = 
0 (SUCCESS)
SUCCESS
26-04-2016 07:15:55.532 UTC Debug memcachedstore.cpp:657: Conditional write 
succeeded to replica 0
26-04-2016 07:15:55.532 UTC Debug authentication.cpp:605: Sending {"impi": 
"2010000...@example.com", "impu": "sip:2010000...@example.com", "nonce": 
"68f9ca7502dd8cd6"} to Chronos to set AV timer
26-04-2016 07:15:55.533 UTC Debug httpconnection.cpp:183: Allocated CURL handle 
0x20a1410
26-04-2016 07:15:55.535 UTC Debug httpresolver.cpp:71: HttpResolver::resolve 
for host 127.0.0.1, port 7253, family 2
26-04-2016 07:15:55.535 UTC Debug baseresolver.cpp:513: Attempt to parse 
127.0.0.1 as IP address
26-04-2016 07:15:55.535 UTC Debug httpresolver.cpp:79: Target is an IP address
26-04-2016 07:15:55.535 UTC Debug httpconnection.cpp:623: Sending HTTP request 
: http://127.0.0.1:7253/timers (trying 127.0.0.1) on new connection
26-04-2016 07:15:55.536 UTC Debug httpconnection.cpp:915: Received header 
http/1.1200ok with value
26-04-2016 07:15:55.536 UTC Debug httpconnection.cpp:915: Received header 
location with value /timers/00f928d5800000040040001000104104
26-04-2016 07:15:55.536 UTC Debug httpconnection.cpp:915: Received header 
content-length with value 0
26-04-2016 07:15:55.536 UTC Debug httpconnection.cpp:915: Received header  with 
value
26-04-2016 07:15:55.537 UTC Debug httpconnection.cpp:638: Received HTTP 
response: status=200, doc=
26-04-2016 07:15:55.537 UTC Debug communicationmonitor.cpp:82: Checking 
communication changes - successful attempts 1, failures 0
26-04-2016 07:15:55.537 UTC Status alarm.cpp:72: sprout issued 1004.1 alarm
26-04-2016 07:15:55.537 UTC Debug pjsip:   tsx0x2088ee8 Transaction created for 
Request msg REGISTER/cseq=1 (rdata0x7f30840a7e48)
26-04-2016 07:15:55.537 UTC Debug pjsip:   tsx0x2088ee8 Incoming Request msg 
REGISTER/cseq=1 (rdata0x7f30840a7e48) in state Null
26-04-2016 07:15:55.537 UTC Debug pjsip:   tsx0x2088ee8 State changed from Null 
to Trying, event=RX_MSG
26-04-2016 07:15:55.537 UTC Debug pjsip:   tsx0x2088ee8 Sending Response msg 
401/REGISTER/cseq=1 (tdta0x2031fb0) in state Trying
26-04-2016 07:15:55.537 UTC Verbose common_sip_processing.cpp:136: TX 635 bytes 
Response msg 401/REGISTER/cseq=1 (tdta0x2031fb0) to TCP 192.168.0.6:43546:
--start msg--

SIP/2.0 401 Unauthorized
Via: SIP/2.0/TCP 
192.168.0.6:43546;rport=43546;received=192.168.0.6;branch=z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7
Via: SIP/2.0/UDP 
10.204.67.13:64453;rport=64453;received=10.204.67.13;branch=z9hG4bK-524287-1---e4bd846009ee2652
Call-ID: 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
From: "2010000006" <sip:2010000...@example.com>;tag=c40b1c7d
To: "2010000006" 
<sip:2010000...@example.com>;tag=z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7
CSeq: 1 REGISTER
WWW-Authenticate: Digest  
realm="example.com",nonce="68f9ca7502dd8cd6",opaque="2439747b31fa04ed",algorithm=MD5,qop="auth"
Content-Length:  0


--end msg--
26-04-2016 07:15:55.537 UTC Debug pjsip:   tsx0x2088ee8 State changed from 
Trying to Completed, event=TX_MSG
26-04-2016 07:15:55.537 UTC Info acr.cpp:660: No CCF or ECF to send ACR for 
session 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM to - dropping!
26-04-2016 07:15:55.537 UTC Debug acr.cpp:54: Destroyed ACR (0x2031d60)
26-04-2016 07:15:55.537 UTC Debug thread_dispatcher.cpp:193: Worker thread 
completed processing message 0x7f30840a7e48
26-04-2016 07:15:55.537 UTC Debug thread_dispatcher.cpp:199: Request latency = 
20963us
26-04-2016 07:15:55.538 UTC Debug pjsip:   tsx0x2088ee8 Timeout timer event
26-04-2016 07:15:55.538 UTC Debug pjsip:   tsx0x2088ee8 State changed from 
Completed to Terminated, event=TIMER
26-04-2016 07:15:55.538 UTC Debug pjsip:   tsx0x2088ee8 Timeout timer event
26-04-2016 07:15:55.538 UTC Debug pjsip:   tsx0x2088ee8 State changed from 
Terminated to Destroyed, event=TIMER
26-04-2016 07:15:55.538 UTC Debug pjsip:  tdta0x2031fb0 Destroying txdata 
Response msg 401/REGISTER/cseq=1 (tdta0x2031fb0)
26-04-2016 07:15:55.538 UTC Debug pjsip:   tsx0x2088ee8 Transaction destroyed!
26-04-2016 07:15:55.871 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg REGISTER/cseq=2 (rdata0x7f3084085620)
26-04-2016 07:15:55.871 UTC Verbose common_sip_processing.cpp:120: RX 1155 
bytes Request msg REGISTER/cseq=2 (rdata0x7f3084085620) from TCP 
192.168.0.6:45479:
--start msg--

REGISTER sip:example.com SIP/2.0
Via: SIP/2.0/TCP 
192.168.0.6:45479;rport;branch=z9hG4bKPjHh.95v0LKU0YoQ.dGWKro2nwnxsqmjD-
Path: <sip:7N8NRxC67H@192.168.0.6:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP 
10.204.67.13:64453;rport=64453;received=10.204.67.13;branch=z9hG4bK-524287-1---c4663316f7e05723
Max-Forwards: 70
Contact: <sip:2010000006@10.204.67.13:64453;rinstance=1608df1e538dd29d>
To: "2010000006" <sip:2010000...@example.com>
From: "2010000006" <sip:2010000...@example.com>;tag=c40b1c7d
Call-ID: 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
CSeq: 2 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, 
MESSAGE
User-Agent: X-Lite release 4.9.3 stamp 79961
Authorization: Digest response="84e4a962481e70859d0683be2d118485", 
username="2010000...@example.com", realm="example.com", 
nonce="68f9ca7502dd8cd6", uri="sip:example.com", algorithm=MD5, 
cnonce="2efa1b9f3e8085a1da26b46debb5424e", opaque="2439747b31fa04ed", qop=auth, 
nc=00000001,integrity-protected=ip-assoc-pending
P-Visited-Network-ID: example.com
Route: <sip:sprout.example.com:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
26-04-2016 07:15:55.871 UTC Debug pjutils.cpp:1662: Logging SAS Call-ID marker, 
Call-ID 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
26-04-2016 07:15:55.871 UTC Debug thread_dispatcher.cpp:253: Queuing cloned 
received message 0x7f30840a7e48 for worker threads
26-04-2016 07:15:55.871 UTC Debug thread_dispatcher.cpp:149: Worker thread 
dequeue message 0x7f30840a7e48
26-04-2016 07:15:55.872 UTC Debug pjsip: sip_endpoint.c Distributing rdata to 
modules: Request msg REGISTER/cseq=2 (rdata0x7f30840a7e48)
26-04-2016 07:15:55.872 UTC Debug uri_classifier.cpp:167: home domain: true, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.872 UTC Debug uri_classifier.cpp:197: Classified URI as 4
26-04-2016 07:15:55.872 UTC Debug authentication.cpp:775: Authentication module 
invoked
26-04-2016 07:15:55.872 UTC Debug authentication.cpp:683: Authorization header 
in request
26-04-2016 07:15:55.872 UTC Debug authentication.cpp:789: Request needs 
authentication
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:195: Key 
impi\\2010000...@example.com hashes to vbucket 55 via hash 0xcc98f437
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:236: Set up new view 1 for 
thread
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:243: Setting up server 0 
for connection 0x7f306800e010 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS 
--POLL-TIMEOUT=250 --BINARY-PROTOCOL)
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:245: Set up connection 
0x7f306800e0c0 to server 192.168.0.5:11211
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:256: Setting server to IP 
address 192.168.0.5 port 11211
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:367: 1 read replicas for 
key impi\\2010000...@example.com
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:402: Attempt to read from 
replica 0 (connection 0x7f306800e0c0)
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:780: Fetch result
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:788: Found record on 
replica
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:410: Read for 
impi\\2010000...@example.com on replica 0 returned SUCCESS
26-04-2016 07:15:55.872 UTC Debug memcachedstore.cpp:453: Read 226 bytes from 
table impi key 2010000...@example.com, CAS = 14
26-04-2016 07:15:55.872 UTC Debug impistore.cpp:786: Retrieved IMPI for 
2010000...@example.com
{"authChallenges":[{"type":"digest","nonce":"68f9ca7502dd8cd6","nc":1,"expires":1461654995,"correlator":"z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7","realm":"example.com","qop":"auth","ha1":"cf2e8e82550b221743c55ed88b1f8a54"}]}
26-04-2016 07:15:55.872 UTC Debug authentication.cpp:908: Verify authentication 
information in request
26-04-2016 07:15:55.873 UTC Debug authentication.cpp:325: Found Digest HA1 = 
cf2e8e82550b221743c55ed88b1f8a54
26-04-2016 07:15:55.873 UTC Debug authentication.cpp:917: Request authenticated 
successfully
26-04-2016 07:15:55.873 UTC Debug impistore.cpp:648: Storing IMPI for 
2010000...@example.com
{"authChallenges":[{"type":"digest","nonce":"68f9ca7502dd8cd6","nc":2,"expires":1461654995,"correlator":"z9hG4bKPjjI-AS7Haoom9nULqfmHJjKUnZcc4IvE7","realm":"example.com","qop":"auth","ha1":"cf2e8e82550b221743c55ed88b1f8a54"}]}
26-04-2016 07:15:55.873 UTC Debug memcachedstore.cpp:542: Writing 226 bytes to 
table impi key 2010000...@example.com, CAS = 14, expiry = 40
26-04-2016 07:15:55.873 UTC Debug memcachedstore.cpp:195: Key 
impi\\2010000...@example.com hashes to vbucket 55 via hash 0xcc98f437
26-04-2016 07:15:55.873 UTC Debug memcachedstore.cpp:562: 1 write replicas for 
key impi\\2010000...@example.com
26-04-2016 07:15:55.873 UTC Debug memcachedstore.cpp:616: Attempt conditional 
write to vbucket 55 on replica 0 (connection 0x7f306800e0c0), CAS = 14, expiry 
= 40
26-04-2016 07:15:55.873 UTC Debug memcachedstore.cpp:657: Conditional write 
succeeded to replica 0
26-04-2016 07:15:55.873 UTC Debug uri_classifier.cpp:167: home domain: true, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.873 UTC Debug uri_classifier.cpp:197: Classified URI as 4
26-04-2016 07:15:55.873 UTC Debug uri_classifier.cpp:167: home domain: false, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.873 UTC Debug uri_classifier.cpp:197: Classified URI as 5
26-04-2016 07:15:55.873 UTC Debug basicproxy.cpp:92: Process REGISTER request
26-04-2016 07:15:55.873 UTC Verbose sproutletproxy.cpp:503: Sproutlet Proxy 
transaction (0x7f30680163a0) created
26-04-2016 07:15:55.873 UTC Debug basicproxy.cpp:1271: Report SAS start marker 
- trail (6)
26-04-2016 07:15:55.873 UTC Debug pjutils.cpp:674: Cloned Request msg 
REGISTER/cseq=2 (rdata0x7f30840a7e48) to tdta0x7f30680167b0
26-04-2016 07:15:55.873 UTC Debug pjsip: tsx0x7f3068018 Transaction created for 
Request msg REGISTER/cseq=2 (rdata0x7f30840a7e48)
26-04-2016 07:15:55.873 UTC Debug pjsip: tsx0x7f3068018 Incoming Request msg 
REGISTER/cseq=2 (rdata0x7f30840a7e48) in state Null
26-04-2016 07:15:55.873 UTC Debug pjsip: tsx0x7f3068018 State changed from Null 
to Trying, event=RX_MSG
26-04-2016 07:15:55.873 UTC Debug basicproxy.cpp:213: tsx0x7f3068018c38 - 
tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying
26-04-2016 07:15:55.873 UTC Debug pjsip:       endpoint Response msg 
408/REGISTER/cseq=2 (tdta0x7f30680193a0) created
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:124: Find target Sproutlet 
for request
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:163: Found next routable 
URI: sip:sprout.example.com:5054;transport=TCP;lr;orig
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:334: Possible service name 
- sprout
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:340: Hostname - example.com
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:334: Possible service name 
- sprout
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:340: Hostname - example.com
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:334: Possible service name 
- sprout
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:340: Hostname - example.com
26-04-2016 07:15:55.873 UTC Debug sproutletproxy.cpp:195: No Sproutlet found 
using service name or host
26-04-2016 07:15:55.874 UTC Debug sproutletproxy.cpp:201: Find default service 
for port 5054
26-04-2016 07:15:55.874 UTC Debug scscfsproutlet.cpp:372: S-CSCF Transaction 
(0x7f306801a3b0) created
26-04-2016 07:15:55.874 UTC Verbose sproutletproxy.cpp:1159: Created Sproutlet 
scscf-0x7f306801a3b0 for Request msg REGISTER/cseq=2 (tdta0x7f30680167b0)
26-04-2016 07:15:55.874 UTC Verbose sproutletproxy.cpp:2067: Routing Request 
msg REGISTER/cseq=2 (tdta0x7f30680167b0) (1182 bytes) to downstream sproutlet 
scscf:
--start msg--

REGISTER sip:example.com SIP/2.0
Via: SIP/2.0/TCP 
192.168.0.6:45479;rport=45479;received=192.168.0.6;branch=z9hG4bKPjHh.95v0LKU0YoQ.dGWKro2nwnxsqmjD-
Path: <sip:7N8NRxC67H@192.168.0.6:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP 
10.204.67.13:64453;rport=64453;received=10.204.67.13;branch=z9hG4bK-524287-1---c4663316f7e05723
Max-Forwards: 70
Contact: <sip:2010000006@10.204.67.13:64453;rinstance=1608df1e538dd29d>
To: "2010000006" <sip:2010000...@example.com>
From: "2010000006" <sip:2010000...@example.com>;tag=c40b1c7d
Call-ID: 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
CSeq: 2 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS, 
MESSAGE
User-Agent: X-Lite release 4.9.3 stamp 79961
Authorization: Digest response="84e4a962481e70859d0683be2d118485", 
username="2010000...@example.com", realm="example.com", 
nonce="68f9ca7502dd8cd6", uri="sip:example.com", algorithm=MD5, 
cnonce="2efa1b9f3e8085a1da26b46debb5424e", opaque="2439747b31fa04ed", qop=auth, 
nc=00000001,integrity-protected=ip-assoc-pending
P-Visited-Network-ID: example.com
Route: <sip:sprout.example.com:5054;transport=TCP;lr;orig>
Content-Length:  0


--end msg--
26-04-2016 07:15:55.874 UTC Debug pjutils.cpp:691: Cloned tdta0x7f30680167b0 to 
tdta0x7f306801a9e0
26-04-2016 07:15:55.874 UTC Debug sproutletproxy.cpp:1220: Remove top Route 
header Route: <sip:sprout.example.com:5054;transport=TCP;lr;orig>
26-04-2016 07:15:55.874 UTC Debug sproutletproxy.cpp:1740: Adding message 
0x7f306801aff0 => txdata 0x7f306801aa88 mapping
26-04-2016 07:15:55.874 UTC Verbose sproutletproxy.cpp:1592: 
scscf-0x7f306801a3b0 pass initial request Request msg REGISTER/cseq=2 
(tdta0x7f306801a9e0) to Sproutlet
26-04-2016 07:15:55.874 UTC Info scscfsproutlet.cpp:414: S-CSCF received 
initial request
26-04-2016 07:15:55.874 UTC Debug uri_classifier.cpp:167: home domain: false, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.874 UTC Debug uri_classifier.cpp:197: Classified URI as 5
26-04-2016 07:15:55.874 UTC Debug scscfsproutlet.cpp:796: No S-CSCF Route 
header, so treat as terminating request
26-04-2016 07:15:55.874 UTC Debug uri_classifier.cpp:167: home domain: true, 
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: 
true, treat_number_as_phone: false
26-04-2016 07:15:55.874 UTC Debug uri_classifier.cpp:197: Classified URI as 4
26-04-2016 07:15:55.874 UTC Debug acr.cpp:1765: Create RalfACR for node type 
S-CSCF with role Terminating
26-04-2016 07:15:55.874 UTC Debug acr.cpp:49: Created ACR (0x7f306801c9d0)
26-04-2016 07:15:55.874 UTC Debug acr.cpp:177: Created S-CSCF Ralf ACR
26-04-2016 07:15:55.874 UTC Debug scscfsproutlet.cpp:978: Looking up iFCs for 
sip:example.com for new AS chain
26-04-2016 07:15:55.874 UTC Debug hssconnection.cpp:585: Making Homestead 
request for /impu/sip%3Aexample.com/reg-data
26-04-2016 07:15:55.875 UTC Debug httpconnection.cpp:183: Allocated CURL handle 
0x7f306801cc80
26-04-2016 07:15:55.876 UTC Debug httpresolver.cpp:71: HttpResolver::resolve 
for host hs.example.com, port 8888, family 2
26-04-2016 07:15:55.877 UTC Debug baseresolver.cpp:513: Attempt to parse 
hs.example.com as IP address
26-04-2016 07:15:55.877 UTC Verbose dnscachedresolver.cpp:240: Check cache for 
hs.example.com type 1
26-04-2016 07:15:55.877 UTC Debug dnscachedresolver.cpp:326: Pulling 1 records 
from cache for hs.example.com A
26-04-2016 07:15:55.877 UTC Debug baseresolver.cpp:361: Found 1 A/AAAA records, 
randomizing
26-04-2016 07:15:55.877 UTC Debug baseresolver.cpp:503: 192.168.0.7:8888 
transport 6 is not blacklisted
26-04-2016 07:15:55.877 UTC Debug baseresolver.cpp:382: Added a server, now 
have 1 of 5
26-04-2016 07:15:55.877 UTC Debug baseresolver.cpp:420: Adding 0 servers from 
blacklist
26-04-2016 07:15:55.877 UTC Debug httpconnection.cpp:623: Sending HTTP request 
: http://hs.example.com:8888/impu/sip%3Aexample.com/reg-data (trying 
192.168.0.7) on new connection
26-04-2016 07:15:55.885 UTC Debug httpconnection.cpp:915: Received header 
http/1.1404notfound with value
26-04-2016 07:15:55.885 UTC Debug httpconnection.cpp:915: Received header 
content-length with value 0
26-04-2016 07:15:55.885 UTC Debug httpconnection.cpp:915: Received header  with 
value
26-04-2016 07:15:55.885 UTC Debug httpconnection.cpp:638: Received HTTP 
response: status=404, doc=
26-04-2016 07:15:55.885 UTC Error httpconnection.cpp:762: cURL failure with 
cURL error code 0 (see man 3 libcurl-errors) and HTTP error code 404
26-04-2016 07:15:55.885 UTC Error hssconnection.cpp:615: Could not get 
subscriber data from HSS
26-04-2016 07:15:55.885 UTC Debug scscfsproutlet.cpp:988: Failed to retrieve 
ServiceProfile for sip:example.com
26-04-2016 07:15:55.885 UTC Debug acr.cpp:216: Set record type for P/S-CSCF
26-04-2016 07:15:55.885 UTC Debug acr.cpp:224: Non-dialog message => 
EVENT_RECORD
26-04-2016 07:15:55.885 UTC Info scscfsproutlet.cpp:459: Failed to determine 
served user for request, reject with 404 status code
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1740: Adding message 
0x7f30680601b0 => txdata 0x7f306805fc48 mapping
26-04-2016 07:15:55.885 UTC Verbose sproutletproxy.cpp:1418: 
scscf-0x7f306801a3b0 sending Response msg 404/REGISTER/cseq=2 
(tdta0x7f306805fba0)
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1747: Removing message 
0x7f306801aff0 => txdata 0x7f306801aa88 mapping
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1495: Free message 
tdta0x7f306801a9e0
26-04-2016 07:15:55.885 UTC Debug pjsip: tdta0x7f306801 Destroying txdata 
Request msg REGISTER/cseq=2 (tdta0x7f306801a9e0)
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1755: Processing actions 
from sproutlet - 1 responses, 0 requests, 0 timers
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1841: Aggregating response 
with status code 404
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1891: 3xx/4xx/5xx/6xx 
response
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1895: Best 3xx/4xx/5xx/6xx 
response so far
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1782: All UAC responded
26-04-2016 07:15:55.885 UTC Debug sproutletproxy.cpp:1747: Removing message 
0x7f30680601b0 => txdata 0x7f306805fc48 mapping
26-04-2016 07:15:55.885 UTC Debug pjsip: tsx0x7f3068018 Sending Response msg 
404/REGISTER/cseq=2 (tdta0x7f306805fba0) in state Trying
26-04-2016 07:15:55.885 UTC Verbose common_sip_processing.cpp:136: TX 509 bytes 
Response msg 404/REGISTER/cseq=2 (tdta0x7f306805fba0) to TCP 192.168.0.6:45479:
--start msg--

SIP/2.0 404 Not Found
Via: SIP/2.0/TCP 
192.168.0.6:45479;rport=45479;received=192.168.0.6;branch=z9hG4bKPjHh.95v0LKU0YoQ.dGWKro2nwnxsqmjD-
Via: SIP/2.0/UDP 
10.204.67.13:64453;rport=64453;received=10.204.67.13;branch=z9hG4bK-524287-1---c4663316f7e05723
Call-ID: 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM
From: "2010000006" <sip:2010000...@example.com>;tag=c40b1c7d
To: "2010000006" 
<sip:2010000...@example.com>;tag=z9hG4bKPjHh.95v0LKU0YoQ.dGWKro2nwnxsqmjD-
CSeq: 2 REGISTER
Content-Length:  0


--end msg--
26-04-2016 07:15:55.886 UTC Debug pjsip: tsx0x7f3068018 State changed from 
Trying to Completed, event=TX_MSG
26-04-2016 07:15:55.886 UTC Debug basicproxy.cpp:213: tsx0x7f3068018c38 - 
tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed
26-04-2016 07:15:55.886 UTC Verbose sproutletproxy.cpp:1833: 
scscf-0x7f306801a3b0 suiciding
26-04-2016 07:15:55.886 UTC Debug sproutletproxy.cpp:1165: Destroying 
SproutletWrapper 0x7f30680161e0
26-04-2016 07:15:55.886 UTC Debug scscfsproutlet.cpp:378: S-CSCF Transaction 
(0x7f306801a3b0) destroyed
26-04-2016 07:15:55.886 UTC Info acr.cpp:660: No CCF or ECF to send ACR for 
session 79961OTk4MmNkZGUzN2QzMTk2MGIwYzFkNjVmODk4MWJhZmM to - dropping!
26-04-2016 07:15:55.886 UTC Debug acr.cpp:54: Destroyed ACR (0x7f306801c9d0)
26-04-2016 07:15:55.886 UTC Debug sproutletproxy.cpp:1174: Free original 
request Request msg REGISTER/cseq=2 (tdta0x7f30680167b0) (tdta0x7f30680167b0)
26-04-2016 07:15:55.886 UTC Debug thread_dispatcher.cpp:193: Worker thread 
completed processing message 0x7f30840a7e48
26-04-2016 07:15:55.886 UTC Debug thread_dispatcher.cpp:199: Request latency = 
14564us
26-04-2016 07:15:55.892 UTC Debug pjsip: tsx0x7f3068018 Timeout timer event
26-04-2016 07:15:55.893 UTC Debug pjsip: tsx0x7f3068018 State changed from 
Completed to Terminated, event=TIMER
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:213: tsx0x7f3068018c38 - 
tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:1281: Report SAS end marker - 
trail (6)
26-04-2016 07:15:55.893 UTC Debug pjsip: tsx0x7f3068018 Timeout timer event
26-04-2016 07:15:55.893 UTC Debug pjsip: tsx0x7f3068018 State changed from 
Terminated to Destroyed, event=TIMER
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:213: tsx0x7f3068018c38 - 
tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed
26-04-2016 07:15:55.893 UTC Debug sproutletproxy.cpp:746: tsx0x7f3068018c38 - 
UAS tsx destroyed
26-04-2016 07:15:55.893 UTC Debug sproutletproxy.cpp:1086: Safe for UASTsx to 
suicide
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:1456: Transaction ((nil)) 
suiciding
26-04-2016 07:15:55.893 UTC Verbose sproutletproxy.cpp:534: Sproutlet Proxy 
transaction (0x7f30680163a0) destroyed
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:467: BasicProxy::UASTsx 
destructor (0x7f30680163a0)
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:484: Disconnect UAC 
transactions from UAS transaction
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:498: Free original request
26-04-2016 07:15:55.893 UTC Debug pjsip: tdta0x7f306801 Destroying txdata 
Request msg REGISTER/cseq=2 (tdta0x7f30680167b0)
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:507: Free un-used best response
26-04-2016 07:15:55.893 UTC Debug pjsip: tdta0x7f306801 Destroying txdata 
Response msg 408/REGISTER/cseq=2 (tdta0x7f30680193a0)
26-04-2016 07:15:55.893 UTC Debug basicproxy.cpp:528: BasicProxy::UASTsx 
destructor completed
26-04-2016 07:15:55.893 UTC Debug pjsip: tdta0x7f306805 Destroying txdata 
Response msg 404/REGISTER/cseq=2 (tdta0x7f306805fba0)
26-04-2016 07:15:55.893 UTC Debug pjsip: tsx0x7f3068018 Transaction destroyed!
26-04-2016 07:15:59.467 UTC Verbose pjsip:    tcplis:5054 TCP listener 
192.168.0.5:5054: got incoming TCP connection from 192.168.0.5:42184, sock=742
26-04-2016 07:15:59.467 UTC Verbose pjsip: tcps0x7f30840a TCP server transport 
created
26-04-2016 07:15:59.468 UTC Debug pjsip: sip_endpoint.c Processing incoming 
message: Request msg OPTIONS/cseq=65319 (rdata0x7f30840a8100)
26-04-2016 07:15:59.468 UTC Verbose common_sip_processing.cpp:120: RX 342 bytes 
Request msg OPTIONS/cseq=65319 (rdata0x7f30840a8100) from TCP 192.168.0.5:42184:
--start msg--

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


--end msg--

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