Jim,
Apologies - I didn't see this new email when I replied to your previous one.
The S-CSCF behavior is divided up into multiple chunks ("Sproutlets"), and we
seem to be invoking the "scscf-proxy" chunk, which is responsible for
processing dialog-related messages (rather than REGISTERs). This is why it is
trying to route the message on towards the "callee" (i.e. the request URI) -
unfortunately, that also resolves to ourselves.
Would you be able to share the logs from the point that the request first hits
Bono, right through until it gets into this loop?
(I think we just have a URI misconfigured somewhere - that should be set up
correctly by the Chef scripts, but there must be a bug there.)
Thanks,
Matt
From: Clearwater [mailto:[email protected]] On
Behalf Of Jim Page
Sent: 21 September 2017 18:26
To: [email protected]
Subject: Re: [Project Clearwater] Looping authentication with Bria
Right - I have made a change in sprout that updates the REGISTER Authorisation
header so that the nc is incremented and a new hash is written into the
response. The authentication is now successful. Unfortunately what happens is
that once the registration is complete, the same REGISTER request is sent over
and over and over to the scscf-proxy sproutlet until the hops limit is reached.
What exactly is supposed to happen here? According to the flow I have, once the
registration on the SCSCF is successful it should send an SAR to the HSS, after
which the SCSCF should return 200 OK to the ISCSCF, and so on back to the UE. I
cannot see any sign the SAR request is taking place, though I can see the UAR
query from the ISCSCF. Here is a section of log from sprout from the moment the
REGISTER is first presented to the scscf-proxy sproutlet until the start of the
first loop:
21-09-2017 15:53:32.239 UTC Debug scscfsproutlet.cpp:489: S-CSCF Transaction
(0x7f474c010e50) created
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:1298: Created Sproutlet
scscf-proxy-0x7f474c010e50 for Request msg REGISTER/cseq=2 (tdta0x7f474c01ce90)
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:2290: Routing Request
msg REGISTER/cseq=2 (tdta0x7f474c01ce90) (1399 bytes) to downstream sproutlet
scscf-proxy:
--start msg—
REGISTER sip:scscf.ims.rmcore.net SIP/2.0
Route: <sip:ims.rmcore.net;lr;service=scscf-proxy>
Via: SIP/2.0/TCP
10.0.0.222:5058;rport=33214;received=10.0.0.222;branch=z9hG4bKPj1JagMaULIh8xrGTU49BsvwXp7aQVjv9S
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP
212.159.106.131:59124;rport=59124;received=212.159.106.131;branch=z9hG4bK-524287-1—07005d66d0f9415a
Max-Forwards: 68
Contact: <sip:[email protected]:59124;rinstance=39865f51c2a988a3>
To: "Jim@IMS" <sip:[email protected]>
From: "Jim@IMS" <sip:[email protected]>;tag=e2a4b510
Call-ID: 85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ
CSeq: 2 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS
User-Agent: Bria 4 release 4.8.2 stamp 85656
P-Visited-Network-ID: ims.rmcore.net<http://ims.rmcore.net>
P-Charging-Function-Addresses: ccf=cdf.ims.rmcore.net<http://cdf.ims.rmcore.net>
P-Charging-Vector:
icid-value="85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ";icid-generated-at=ec2-52-56-52-145.eu-west-2.compute.amazonaws.com<http://ec2-52-56-52-145.eu-west-2.compute.amazonaws.com>
Authorization: Digest response="5a39ea19aeafcf955924b29a9a375451",
username="[email protected]<mailto:[email protected]>",
realm="ims.rmcore.net<http://ims.rmcore.net>", nonce="63bff4bb68c27b47",
uri="sip:ims.rmcore.net", algorithm=MD5,
cnonce="c549e7ca56a2867a6e23caf77a3c629a", opaque="5a5a8de45658f637", qop=auth,
nc=00000002,integrity-protected=ip-assoc-pending
Content-Length: 0
--end msg—
21-09-2017 15:53:32.239 UTC Debug pjutils.cpp:700: Cloned tdta0x7f474c01ce90 to
tdta0x7f474c020150
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:1364: Remove top Route
header Route: <sip:ims.rmcore.net;lr;service=scscf-proxy>
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:1961: Adding message
0x7f474c020760 => txdata 0x7f474c0201f8 mapping
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:1806:
scscf-proxy-0x7f474c010e50 pass initial request Request msg REGISTER/cseq=2
(tdta0x7f474c020150) to Sproutlet
21-09-2017 15:53:32.239 UTC Info scscfsproutlet.cpp:536: S-CSCF received
initial request
21-09-2017 15:53:32.239 UTC Debug uri_classifier.cpp:139: home domain: true,
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip:
true, treat_number_as_phone: false
21-09-2017 15:53:32.239 UTC Debug uri_classifier.cpp:185: Classified URI as 4
21-09-2017 15:53:32.239 UTC Debug scscfsproutlet.cpp:993: Route header
references this system
21-09-2017 15:53:32.239 UTC Debug scscfsproutlet.cpp:1039: No ODI token, or
invalid ODI token, on request - logging ICID marker
85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ for B2BUA AS correlation
21-09-2017 15:53:32.239 UTC Debug scscfsproutlet.cpp:1052: Got our Route
header, session case term, OD=None
21-09-2017 15:53:32.239 UTC Debug uri_classifier.cpp:139: home domain: false,
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip:
true, treat_number_as_phone: false
21-09-2017 15:53:32.239 UTC Debug uri_classifier.cpp:185: Classified URI as 5
21-09-2017 15:53:32.239 UTC Debug scscfsproutlet.cpp:1396: URI is not locally
hosted
21-09-2017 15:53:32.239 UTC Debug acr.cpp:1787: Create RalfACR for node type
S-CSCF with role Terminating
21-09-2017 15:53:32.239 UTC Debug acr.cpp:24: Created ACR (0x7f474c022110)
21-09-2017 15:53:32.239 UTC Debug acr.cpp:164: Created S-CSCF Ralf ACR
21-09-2017 15:53:32.239 UTC Debug acr.cpp:29: Destroyed ACR (0x7f474c022110)
21-09-2017 15:53:32.239 UTC Info scscfsproutlet.cpp:714: Route request without
applying services
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:1535: Sproutlet
send_request 0x7f474c020760
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:1576:
scscf-proxy-0x7f474c010e50 sending Request msg REGISTER/cseq=2
(tdta0x7f474c020150) on fork 0
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:1976: Processing actions
from sproutlet - 0 responses, 1 requests, 0 timers
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:2016: Processing request
0x7f474c0201f8, fork = 0
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:2141:
scscf-proxy-0x7f474c010e50 transmitting request on fork 0
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:2156:
scscf-proxy-0x7f474c010e50 store reference to non-ACK request Request msg
REGISTER/cseq=2 (tdta0x7f474c020150) on fork 0
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:1968: Removing message
0x7f474c020760 => txdata 0x7f474c0201f8 mapping
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:163: Find target Sproutlet
for request
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:197: Found next routable
URI: sip:scscf.ims.rmcore.net
21-09-2017 15:53:32.239 UTC Debug sproutletproxy.cpp:340: Possible service name
scscf will be used if ims.rmcore.net<http://ims.rmcore.net> is a local hostname
21-09-2017 15:53:32.239 UTC Debug authenticationsproutlet.cpp:169:
Authorization header in request
21-09-2017 15:53:32.239 UTC Debug authenticationsproutlet.cpp:177: Integrity
protected with ip-assoc-pending
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:1298: Created Sproutlet
authentication-0x7f474c022150 for Request msg REGISTER/cseq=2
(tdta0x7f474c020150)
21-09-2017 15:53:32.239 UTC Verbose sproutletproxy.cpp:2290: Routing Request
msg REGISTER/cseq=2 (tdta0x7f474c020150) (1347 bytes) to downstream sproutlet
authentication:
--start msg—
REGISTER sip:scscf.ims.rmcore.net SIP/2.0
Via: SIP/2.0/TCP
10.0.0.222:5058;rport=33214;received=10.0.0.222;branch=z9hG4bKPj1JagMaULIh8xrGTU49BsvwXp7aQVjv9S
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP
212.159.106.131:59124;rport=59124;received=212.159.106.131;branch=z9hG4bK-524287-1—07005d66d0f9415a
Max-Forwards: 67
Contact: <sip:[email protected]:59124;rinstance=39865f51c2a988a3>
To: "Jim@IMS" <sip:[email protected]>
From: "Jim@IMS" <sip:[email protected]>;tag=e2a4b510
Call-ID: 85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ
CSeq: 2 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS
User-Agent: Bria 4 release 4.8.2 stamp 85656
P-Visited-Network-ID: ims.rmcore.net<http://ims.rmcore.net>
P-Charging-Function-Addresses: ccf=cdf.ims.rmcore.net<http://cdf.ims.rmcore.net>
P-Charging-Vector:
icid-value="85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ";icid-generated-at=ec2-52-56-52-145.eu-west-2.compute.amazonaws.com<http://ec2-52-56-52-145.eu-west-2.compute.amazonaws.com>
Authorization: Digest response="5a39ea19aeafcf955924b29a9a375451",
username="[email protected]<mailto:[email protected]>",
realm="ims.rmcore.net<http://ims.rmcore.net>", nonce="63bff4bb68c27b47",
uri="sip:ims.rmcore.net", algorithm=MD5,
cnonce="c549e7ca56a2867a6e23caf77a3c629a", opaque="5a5a8de45658f637", qop=auth,
nc=00000002,integrity-protected=ip-assoc-pending
Content-Length: 0
--end msg—
21-09-2017 15:53:32.240 UTC Debug pjutils.cpp:700: Cloned tdta0x7f474c020150 to
tdta0x7f474c022360
21-09-2017 15:53:32.240 UTC Debug sproutletproxy.cpp:1961: Adding message
0x7f474c022970 => txdata 0x7f474c022408 mapping
21-09-2017 15:53:32.240 UTC Verbose sproutletproxy.cpp:1806:
authentication-0x7f474c022150 pass initial request Request msg REGISTER/cseq=2
(tdta0x7f474c022360) to Sproutlet
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:873:
Authentication module invoked
21-09-2017 15:53:32.240 UTC Debug sproutletproxy.cpp:340: Possible service name
scscf will be used if sprout.ims.rmcore.net<http://sprout.ims.rmcore.net> is a
local hostname
21-09-2017 15:53:32.240 UTC Debug sproutletproxy.cpp:340: Possible service name
scscf will be used if ims.rmcore.net<http://ims.rmcore.net> is a local hostname
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:1456: Lookup IMPI
object: [email protected]<mailto:[email protected]>
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:295: Start GET from table
impi for key [email protected]<mailto:[email protected]>
21-09-2017 15:53:32.240 UTC Debug astaire_resolver.cpp:47:
AstaireResolver::resolve for host
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>, family 2
21-09-2017 15:53:32.240 UTC Debug utils.cpp:377: Malformed host/port
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>
21-09-2017 15:53:32.240 UTC Debug utils.cpp:418: Attempt to parse
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> as IP address
21-09-2017 15:53:32.240 UTC Verbose dnscachedresolver.cpp:468: Check cache for
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> type 1
21-09-2017 15:53:32.240 UTC Debug dnscachedresolver.cpp:570: Pulling 1 records
from cache for vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> A
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:369: Found 1 A/AAAA records,
creating iterator
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:920: Attempting to get 2
targets for host:vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>.
allowed_host_state = 3
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:793:
10.0.0.6:11311;transport=TCP has state: WHITE
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:793:
10.0.0.6:11311;transport=TCP has state: WHITE
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:997: Added a whitelisted
server to targets, now have 1 of 2
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:696: Found 1 targets for
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:721: Duplicate target
IP=10.0.0.6, port= 11311 as it is the only target
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:249: Try server IP
10.0.0.6, port 11311
21-09-2017 15:53:32.240 UTC Debug connection_pool.h:207: Request for connection
to IP: 10.0.0.6, port: 11311
21-09-2017 15:53:32.240 UTC Debug connection_pool.h:220: Found existing
connection 0x7f470c06a3e0 in pool
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:74: Fetch result
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:82: Found record on replica
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:260: libmemcached returned 0
21-09-2017 15:53:32.240 UTC Debug connection_pool.h:244: Release connection to
IP: 10.0.0.6, port: 11311 to pool
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:339: Read 268 bytes from
table impi key [email protected]<mailto:[email protected]>,
CAS = 18873
21-09-2017 15:53:32.240 UTC Debug astaire_impistore.cpp:177: Retrieved IMPI for
[email protected]<mailto:[email protected]>
{"authChallenges":[{"type":"digest","nonce":"63bff4bb68c27b47","nc":2,"expires":1506009512,"correlator":"z9hG4bKPj868.WzubxOAj3T1s2dS1BU0qM0Zj-kpZ","scscf-uri":"sip:scscf.ims.rmcore.net","realm":"ims.rmcore.net<http://ims.rmcore.net>","qop":"auth","ha1":"b144b84f59356acbb86048bf3eb5f48f”}]}
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:994: Verify
authentication information in request
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:482: Found Digest
HA1 = b144b84f59356acbb86048bf3eb5f48f
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:1006: Request
authenticated successfully
21-09-2017 15:53:32.240 UTC Debug authenticationsproutlet.cpp:1033: Storing
challenge because nonce counts are supported
21-09-2017 15:53:32.240 UTC Debug astaire_impistore.cpp:134: Storing IMPI for
[email protected]<mailto:[email protected]>
{"authChallenges":[{"type":"digest","nonce":"63bff4bb68c27b47","nc":3,"expires":1506009512,"correlator":"z9hG4bKPj868.WzubxOAj3T1s2dS1BU0qM0Zj-kpZ","scscf-uri":"sip:scscf.ims.rmcore.net","realm":"ims.rmcore.net<http://ims.rmcore.net>","qop":"auth","ha1":"b144b84f59356acbb86048bf3eb5f48f”}]}
21-09-2017 15:53:32.240 UTC Debug memcachedstore.cpp:413: Writing 268 bytes to
table impi key [email protected]<mailto:[email protected]>,
CAS = 18873, expiry = 300
21-09-2017 15:53:32.240 UTC Debug astaire_resolver.cpp:47:
AstaireResolver::resolve for host
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>, family 2
21-09-2017 15:53:32.240 UTC Debug utils.cpp:377: Malformed host/port
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>
21-09-2017 15:53:32.240 UTC Debug utils.cpp:418: Attempt to parse
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> as IP address
21-09-2017 15:53:32.240 UTC Verbose dnscachedresolver.cpp:468: Check cache for
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> type 1
21-09-2017 15:53:32.240 UTC Debug dnscachedresolver.cpp:570: Pulling 1 records
from cache for vellum.ims.rmcore.net<http://vellum.ims.rmcore.net> A
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:369: Found 1 A/AAAA records,
creating iterator
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:920: Attempting to get 2
targets for host:vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>.
allowed_host_state = 3
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:793:
10.0.0.6:11311;transport=TCP has state: WHITE
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:793:
10.0.0.6:11311;transport=TCP has state: WHITE
21-09-2017 15:53:32.240 UTC Debug baseresolver.cpp:997: Added a whitelisted
server to targets, now have 1 of 2
21-09-2017 15:53:32.241 UTC Debug memcachedstore.cpp:696: Found 1 targets for
vellum.ims.rmcore.net<http://vellum.ims.rmcore.net>
21-09-2017 15:53:32.241 UTC Debug memcachedstore.cpp:721: Duplicate target
IP=10.0.0.6, port= 11311 as it is the only target
21-09-2017 15:53:32.241 UTC Debug memcachedstore.cpp:249: Try server IP
10.0.0.6, port 11311
21-09-2017 15:53:32.241 UTC Debug connection_pool.h:207: Request for connection
to IP: 10.0.0.6, port: 11311
21-09-2017 15:53:32.241 UTC Debug connection_pool.h:220: Found existing
connection 0x7f470c06a3e0 in pool
21-09-2017 15:53:32.241 UTC Debug memcachedstore.cpp:260: libmemcached returned 0
21-09-2017 15:53:32.241 UTC Debug connection_pool.h:244: Release connection to
IP: 10.0.0.6, port: 11311 to pool
21-09-2017 15:53:32.241 UTC Debug memcachedstore.cpp:555: Write successful
21-09-2017 15:53:32.241 UTC Debug authenticationsproutlet.cpp:1178: Updated
Authorization header with new nc and response
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:427: Creating URI for
service registrar
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:340: Possible service name
scscf will be used if ims.rmcore.net<http://ims.rmcore.net> is a local hostname
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:453: Constructed URI
sip:ims.rmcore.net;lr;service=registrar
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:1535: Sproutlet
send_request 0x7f474c022970
21-09-2017 15:53:32.241 UTC Verbose sproutletproxy.cpp:1576:
authentication-0x7f474c022150 sending Request msg REGISTER/cseq=2
(tdta0x7f474c022360) on fork 0
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:1976: Processing actions
from sproutlet - 0 responses, 1 requests, 0 timers
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:2016: Processing request
0x7f474c022408, fork = 0
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:2141:
authentication-0x7f474c022150 transmitting request on fork 0
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:2156:
authentication-0x7f474c022150 store reference to non-ACK request Request msg
REGISTER/cseq=2 (tdta0x7f474c022360) on fork 0
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:1968: Removing message
0x7f474c022970 => txdata 0x7f474c022408 mapping
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:163: Find target Sproutlet
for request
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:197: Found next routable
URI: sip:ims.rmcore.net;lr;service=registrar
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:300: Found services param
- registrar
21-09-2017 15:53:32.241 UTC Debug uri_classifier.cpp:139: home domain: false,
local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip:
true, treat_number_as_phone: false
21-09-2017 15:53:32.241 UTC Debug uri_classifier.cpp:185: Classified URI as 5
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:427: Creating URI for
service subscription
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:300: Found services param
- registrar
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:453: Constructed URI
sip:ims.rmcore.net;lr;service=subscription
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:1200: Remove top Route
header Route: <sip:ims.rmcore.net;lr;service=registrar>
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:163: Find target Sproutlet
for request
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:197: Found next routable
URI: sip:ims.rmcore.net;lr;service=subscription
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:300: Found services param
- subscription
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:427: Creating URI for
service scscf-proxy
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:300: Found services param
- subscription
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:453: Constructed URI
sip:ims.rmcore.net;lr;service=scscf-proxy
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:1200: Remove top Route
header Route: <sip:ims.rmcore.net;lr;service=subscription>
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:163: Find target Sproutlet
for request
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:197: Found next routable
URI: sip:ims.rmcore.net;lr;service=scscf-proxy
21-09-2017 15:53:32.241 UTC Debug sproutletproxy.cpp:300: Found services param
- scscf-proxy
21-09-2017 15:53:32.241 UTC Debug scscfsproutlet.cpp:489: S-CSCF Transaction
(0x7f474c011150) created
21-09-2017 15:53:32.241 UTC Verbose sproutletproxy.cpp:1298: Created Sproutlet
scscf-proxy-0x7f474c011150 for Request msg REGISTER/cseq=2 (tdta0x7f474c022360)
21-09-2017 15:53:32.241 UTC Verbose sproutletproxy.cpp:2290: Routing Request
msg REGISTER/cseq=2 (tdta0x7f474c022360) (1399 bytes) to downstream sproutlet
scscf-proxy:
--start msg—
REGISTER sip:scscf.ims.rmcore.net SIP/2.0
Route: <sip:ims.rmcore.net;lr;service=scscf-proxy>
Via: SIP/2.0/TCP
10.0.0.222:5058;rport=33214;received=10.0.0.222;branch=z9hG4bKPj1JagMaULIh8xrGTU49BsvwXp7aQVjv9S
Path: <sip:[email protected]:5058;transport=TCP;lr;ob>
Via: SIP/2.0/UDP
212.159.106.131:59124;rport=59124;received=212.159.106.131;branch=z9hG4bK-524287-1—07005d66d0f9415a
Max-Forwards: 66
Contact: <sip:[email protected]:59124;rinstance=39865f51c2a988a3>
To: "Jim@IMS" <sip:[email protected]>
From: "Jim@IMS" <sip:[email protected]>;tag=e2a4b510
Call-ID: 85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ
CSeq: 2 REGISTER
Expires: 3600
Allow: SUBSCRIBE, NOTIFY, INVITE, ACK, CANCEL, BYE, REFER, INFO, OPTIONS
User-Agent: Bria 4 release 4.8.2 stamp 85656
P-Visited-Network-ID: ims.rmcore.net<http://ims.rmcore.net>
P-Charging-Function-Addresses: ccf=cdf.ims.rmcore.net<http://cdf.ims.rmcore.net>
P-Charging-Vector:
icid-value="85656NGM0NGZkNDM3YjVhZTNhZWY3OWNmYzQ1NDc4MjM3ZTQ";icid-generated-at=ec2-52-56-52-145.eu-west-2.compute.amazonaws.com<http://ec2-52-56-52-145.eu-west-2.compute.amazonaws.com>
Authorization: Digest response="54ade38e11b464bf9fcde6f464c7d9e8",
username="[email protected]<mailto:[email protected]>",
realm="ims.rmcore.net<http://ims.rmcore.net>", nonce="63bff4bb68c27b47",
uri="sip:ims.rmcore.net", algorithm=MD5,
cnonce="c549e7ca56a2867a6e23caf77a3c629a", opaque="5a5a8de45658f637", qop=auth,
nc=00000003,integrity-protected=ip-assoc-pending
Content-Length: 0
--end msg—
Any idea what’s going wrong here?
Thanks
Jim
RedMatter Ltd
Jim Page
VP Mobile Services
+44 (0)333 150 1666
+44 (0)7870 361412
[email protected]<mailto:[email protected]>
On 21 Sep 2017, at 15:38, Jim Page
<[email protected]<mailto:[email protected]>> wrote:
Hi Clearwater people
I could really do with your help with the below. I have a pretty much bog
standard setup, standard build with chef in AWS, plus an openimscore HSS
instance. I am currently unable to get any sip devices to register due to an
apparent issue nonce counting. Can you help? In parallel I am trying to hack
the code to work around the issue … but I can’t believe this isn’t a common
scenario with a simple solution … ?
Thanks in advance …
Jim
RedMatter Ltd
Jim Page
VP Mobile Services
+44 (0)333 150 1666
+44 (0)7870 361412
[email protected]<mailto:[email protected]>
On 17 Sep 2017, at 18:38, Jim Page
<[email protected]<mailto:[email protected]>> wrote:
Hi There
I initially set up my IMS in an AWS VPC, using chef. It worked out of the box
without an HSS, I was able to use Ellis to provision accounts and they
registered no problem using Bria 4. I decided to add an HSS (using ‘knife box’
to add an openimscore HSS instance) so that I can test our application servers.
Now that I have the HSS integrated (there were niggles in the installation), I
provisioned a new user on the HSS but the Bria phone will not authenticate, and
a feedback loop is generated on the first REGISTER attempt. The problem seems
to be related to nonce counting. The process seems to go like this:
UE REGISTER -> Bono
Bono REGISTER -> icscf
No Authorization. Challenge is built, and IMPI is created with nc=1, and
stored
icscf 401 -> Bono
Bono 401 -> UE
UE builds an Authorisation header
UE REGISTER -> Bono
Bono REGISTER -> icscf
The Authorisation header contains nc=000001.
IMPI is loaded and validation is successful.
IMPI is stored with nc=2, log line 'Debug authenticationsproutlet.cpp:1033:
Storing challenge because nonce counts are supported’
icscf REGISTER -> scscf-proxy
The Authorisation header still contains nc=000001.
IMPI is loaded, but log line says: 'Info authenticationsproutlet.cpp:971:
Nonce count supplied (1) is lower than expected (2) - ignore it’
The Authorisation header is ignored and another 401 challenge is issued, and
the UE responds …. and this causes a loop
scscf-proxy 401 -> icscf
icscf 401 -> Bono
Bono 401 -> UE
There seems to be a fundamental flaw here. The IMPI nc is incrementing, but the
Authorisation header is not. I can’t see how this can work unless icscf
increments nc in the authorisation header before sending it to the scscf
Also please note: I disabled nonce_count_supported in shared_config, but the
result was a log line ‘nonce count is supplied but not supported’ (or words to
that effect) and the Authorisation header is again ignored, and there is a loop.
How to move forward from here? I have searched in vain for a way to disable
nonce count in Bria 4.
I can provide logs if helpful, but they are long and I don’t want to clog
everyone’s inbox.
Kind regards
Jim
RedMatter Ltd
Jim Page
VP Mobile Services
+44 (0)333 150 1666
+44 (0)7870 361412
[email protected]<mailto:[email protected]>
_______________________________________________
Clearwater mailing list
[email protected]<mailto:[email protected]>
http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
_______________________________________________
Clearwater mailing list
[email protected]<mailto:[email protected]>
http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
_______________________________________________
Clearwater mailing list
[email protected]
http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
