Hi Daniel, Apologies for the delay in getting back to you.
It seems likely that the problem you are experiencing as a result of a missing or incorrect P-Asserted-Identity header on the OPTIONS request. This header is used to identify which IFCs to invoke, so if it isn't set correctly, the IFCs that would direct your request to the AS won't have any effect. Without any IFCs, the best sprout can do is forward the request on. If you're sending the request via a P-CSCF, the P-CSCF should add this header to the request, but if you're sending the message directly to sprout, you'll have to add it yourself. If you're looking to poll the health of the AS, you may be better off sending the request directly to the AS. In order to help any further, I'll need a bit more information. First of all, are you sending the request directly to the sprout, or via a P-CSCF? Also, could you supply sprout debug logs containing the full text of the OPTIONS request, and, if you're sending the request via bono, the corresponding debug logs from that process too. Thanks, Tom From: Clearwater [mailto:clearwater-boun...@lists.projectclearwater.org] On Behalf Of Daniel Marques Sent: 29 March 2018 14:50 To: clearwater@lists.projectclearwater.org<mailto:clearwater@lists.projectclearwater.org> Subject: [Project Clearwater] Sprout sending OPTIONS to sprout and not AS Hi I am setting up one clearwater environment using docker. I have successfully deployed the ims containers and two AS with IFCs. The REGISTER requests work with success and reach the AS. The OPTIONS requests don't work ( i have copied the IFCs from an older installation of clearwater, so I believe that the format of the IFCs is OK). I took a pcap in sprout, and what I observe is that sprout receives the OPTIONS and executes a NAPTR dns query to the user domain. The resulting dns query points the request to sprout again. I believe that instead of sprout attempting to execute the above dns query, should check the IFCs and send the OPTIONS towards the AS. Can anyone help me with this? I send here a part of the logs. 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug pjsip: sip_endpoint.c Processing incoming message: Request msg OPTIONS/cseq=1 (rdata0x7f21b4068500) 29-03-2018 13:45:19.173 UTC [7f21b8819700] Verbose common_sip_processing.cpp:87: RX 1686 bytes Request msg OPTIONS/cseq=1 (rdata0x7f21b4068500) from TCP 172.50.0.9:38087: --start msg-- OPTIONS sip:+917722000...@ims.mnc874.mcc405.3gppnetwork.org SIP/2.0 Record-Route: <sip:172.50.0.9:5058;transport=TCP;lr> ... Route: <sip:sprout:5054;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f> Content-Length: 0 ... --end msg-- 29-03-2018 13:45:19.173 UTC [7f21b8819700] 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 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug pjutils.cpp:1771: Logging SAS Call-ID marker, Call-ID mHkJ0rybfT 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug thread_dispatcher.cpp:554: Recieved message 0x7f21b4068500 on worker thread 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug thread_dispatcher.cpp:571: Admitted request 0x7f21b4068500 on worker thread 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug thread_dispatcher.cpp:606: Incoming message 0x7f21b4068500 cloned to 0x7f21b406ba18 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug thread_dispatcher.cpp:625: Queuing cloned received message 0x7f21b406ba18 for worker threads with priority 15 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x21b2ad8 29-03-2018 13:45:19.173 UTC [7f21b8819700] Debug event_statistic_accumulator.cpp:32: Accumulate 0 for 0x21b2b20 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug utils.cpp:872: Added IOHook 0x7f25927cbe30 to stack. There are now 1 hooks 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug thread_dispatcher.cpp:178: Worker thread dequeue message 0x7f21b406ba18 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug thread_dispatcher.cpp:183: Request latency so far = 278us 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg OPTIONS/cseq=1 (rdata0x7f21b406ba18) 29-03-2018 13:45:19.173 UTC [7f25927cc700] 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 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug basicproxy.cpp:62: Process OPTIONS request 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug sproutletproxy.cpp:631: Sproutlet Proxy transaction (0x7f219c021810) created. There are now 1 instances 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug basicproxy.cpp:1318: Report SAS start marker - trail (f) 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjutils.cpp:719: Cloned Request msg OPTIONS/cseq=1 (rdata0x7f21b406ba18) to tdta0x7f219c021c60 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjsip: tsx0x7f219c025 Transaction created for Request msg OPTIONS/cseq=1 (rdata0x7f21b406ba18) 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjsip: tsx0x7f219c025 Incoming Request msg OPTIONS/cseq=1 (rdata0x7f21b406ba18) in state Null 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjsip: tsx0x7f219c025 State changed from Null to Trying, event=RX_MSG 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug basicproxy.cpp:183: tsx0x7f219c025098 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug pjsip: endpoint Response msg 408/OPTIONS/cseq=1 (tdta0x7f219c025800) created 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug sproutletproxy.cpp:165: Find target Sproutlet for request 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug sproutletproxy.cpp:199: Found next routable URI: sip:sprout:5054;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug sproutletproxy.cpp:237: No Sproutlet found using service name or host 29-03-2018 13:45:19.173 UTC [7f25927cc700] Debug sproutletproxy.cpp:243: Find default service for port 5054 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:429: Creating URI for service registrar 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:455: Constructed URI sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=registrar 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1276: Remove top Route header Route: <sip:sprout:5054;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f> 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:165: Find target Sproutlet for request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:199: Found next routable URI: sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=registrar 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:302: Found services param - registrar 29-03-2018 13:45:19.174 UTC [7f25927cc700] 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 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:429: Creating URI for service subscription 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:302: Found services param - registrar 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:455: Constructed URI sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=subscription 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1276: Remove top Route header Route: <sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=registrar> 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:165: Find target Sproutlet for request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:199: Found next routable URI: sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=subscription 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:302: Found services param - subscription 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:429: Creating URI for service scscf-proxy 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:302: Found services param - subscription 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:455: Constructed URI sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=scscf-proxy 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1276: Remove top Route header Route: <sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=subscription> 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:165: Find target Sproutlet for request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:199: Found next routable URI: sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=scscf-proxy 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:302: Found services param - scscf-proxy 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug scscfsproutlet.cpp:424: S-CSCF Transaction (0x7f219c0278f0) created 29-03-2018 13:45:19.174 UTC [7f25927cc700] Verbose sproutletproxy.cpp:1384: Created Sproutlet scscf-proxy-0x7f219c0278f0 for Request msg OPTIONS/cseq=1 (tdta0x7f219c021c60) 29-03-2018 13:45:19.174 UTC [7f25927cc700] Verbose sproutletproxy.cpp:2487: Routing Request msg OPTIONS/cseq=1 (tdta0x7f219c021c60) (1727 bytes) to downstream sproutlet scscf-proxy: --start msg-- OPTIONS sip:+917722000...@ims.mnc874.mcc405.3gppnetwork.org SIP/2.0 Route: <sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=scscf-proxy> Record-Route: <sip:172.50.0.9:5058;transport=TCP;lr> ... --end msg-- 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2504: Network function boundary: yes ('EXTERNAL'->'scscf'/'scscf-proxy') 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2504: Network function boundary: yes ('EXTERNAL'->'scscf'/'scscf-proxy') 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2517: Internal network function boundary: no 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug pjutils.cpp:736: Cloned tdta0x7f219c021c60 to tdta0x7f219c028430 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1450: Remove top Route header Route: <sip:sprout;transport=tcp;lr;orig;username=+917722000103%40ims.mnc874.mcc405.3gppnetwork.org;nonce=7061e85c400e635f;service=scscf-proxy> 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2115: Adding message 0x7f219c028a40 => txdata 0x7f219c0284d8 mapping 29-03-2018 13:45:19.174 UTC [7f25927cc700] Verbose sproutletproxy.cpp:1946: scscf-proxy-0x7f219c0278f0 pass initial request Request msg OPTIONS/cseq=1 (tdta0x7f219c028430) to Sproutlet 29-03-2018 13:45:19.174 UTC [7f25927cc700] Info scscfsproutlet.cpp:471: S-CSCF received initial request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:139: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 3 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug scscfsproutlet.cpp:945: Route header references this system 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug scscfsproutlet.cpp:998: No ODI token, or invalid ODI token, on request, and no P-Charging-Vector header (so can't log ICID for correlation) 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug scscfsproutlet.cpp:1004: Got our Route header, session case orig, OD=None 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug pjutils.cpp:294: Served user from P-Asserted-Identity header 29-03-2018 13:45:19.174 UTC [7f25927cc700] 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 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.174 UTC [7f25927cc700] 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 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug scscfsproutlet.cpp:1348: URI is not locally hosted 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug acr.cpp:1797: Create RalfACR for node type S-CSCF with role Originating 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug acr.cpp:24: Created ACR (0x7f219c02b3a0) 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug acr.cpp:170: Created S-CSCF Ralf ACR 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug acr.cpp:29: Destroyed ACR (0x7f219c02b3a0) 29-03-2018 13:45:19.174 UTC [7f25927cc700] 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 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug uri_classifier.cpp:172: Classified URI as 5 29-03-2018 13:45:19.174 UTC [7f25927cc700] Info scscfsproutlet.cpp:656: Route request without applying services 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1621: Sproutlet send_request 0x7f219c028a40 29-03-2018 13:45:19.174 UTC [7f25927cc700] Verbose sproutletproxy.cpp:1662: scscf-proxy-0x7f219c0278f0 sending Request msg OPTIONS/cseq=1 (tdta0x7f219c028430) on fork 0 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2130: Processing actions from sproutlet - 0 responses, 1 requests, 0 timers 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2170: Processing request 0x7f219c0284d8, fork = 0 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2334: scscf-proxy-0x7f219c0278f0 transmitting request on fork 0 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2349: scscf-proxy-0x7f219c0278f0 store reference to non-ACK request Request msg OPTIONS/cseq=1 (tdta0x7f219c028430) on fork 0 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:2122: Removing message 0x7f219c028a40 => txdata 0x7f219c0284d8 mapping 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:165: Find target Sproutlet for request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:199: Found next routable URI: sip:+917722000...@ims.mnc874.mcc405.3gppnetwork.org 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:342: Possible service name ims will be used if mnc874.mcc405.3gppnetwork.org is a local hostname 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:365: Found user part - +917722000104 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sproutletproxy.cpp:1007: No local sproutlet matches request 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug pjsip: tsx0x7f219c02b Transaction created for Request msg OPTIONS/cseq=1 (tdta0x7f219c028430) 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug basicproxy.cpp:1669: Added trail identifier 15 to UAC transaction 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug pjutils.cpp:510: Next hop node is encoded in Request-URI 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug sipresolver.cpp:84: SIPResolver::resolve for name ims.mnc874.mcc405.3gppnetwork.org, port 0, transport -1, family 2 29-03-2018 13:45:19.174 UTC [7f25927cc700] Debug utils.cpp:446: Attempt to parse ims.mnc874.mcc405.3gppnetwork.org as IP address 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug sipresolver.cpp:147: Do NAPTR look-up for ims.mnc874.mcc405.3gppnetwork.org 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug ttlcache.h:200: Time now is 1522331119, expiry time of entry at head of expiry list is 1522330274 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug ttlcache.h:93: Entry not in cache, so create new entry 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug baseresolver.cpp:252: NAPTR cache factory called for ims.mnc874.mcc405.3gppnetwork.org 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug baseresolver.cpp:264: Sending DNS NAPTR query for ims.mnc874.mcc405.3gppnetwork.org 29-03-2018 13:45:19.175 UTC [7f25927cc700] Verbose dnscachedresolver.cpp:468: Check cache for ims.mnc874.mcc405.3gppnetwork.org type 35 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug dnscachedresolver.cpp:474: No entry found in cache 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug dnscachedresolver.cpp:477: Create cache entry pending query 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug dnscachedresolver.cpp:525: Create and execute DNS query transaction 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug dnscachedresolver.cpp:538: Wait for query responses 29-03-2018 13:45:19.175 UTC [7f25927cc700] Debug thread_dispatcher.cpp:117: Pausing stopwatch due to DNS query Thanks Daniel
_______________________________________________ Clearwater mailing list Clearwater@lists.projectclearwater.org http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
