Hi Abaco, I believe Sprout is behaving correctly. It receives a PRACK, and follows the route set on it. It then sends the request to the Request URI, but the terminating SBC rejects it. The RequestURI should have been set to the Contact header on the 1xx response that generated the PRACK.
This suggests that either the SBC that sends the 1xx response isn’t correctly setting the Contact header to a value that will be accepted by the SBC, or the SBC that sends on the PRACK isn’t correctly setting the RequestURI to the received Contact header. What SBC are you using? Ellie From: Ruggero Schiavi [mailto:[email protected]] Sent: 28 November 2014 08:00 To: Eleanor Merry Cc: [email protected] Subject: Re: [Clearwater] PRACK PROBLEM HI Ellie, Thanks for your reply. As your requested here you can find the Sprout Log from the received Prack to the Method not allowed message received by the SBC. Please let me know your opinion, Regards, Abaco 28-11-2014 07:37:57.804 UTC Verbose stack.cpp:239: RX 624 bytes Request msg PRACK/cseq=286923527 (rdata0x20367e8) from UDP [sbc.private.ip.address]:5060: --start msg-- PRACK sip:87100004@[sbc.private.ip.address]:5060;rinstance=ebdc3f2d5251207f;dtg=TG_PCSCF_INT_IP SIP/2.0 Via: SIP/2.0/UDP [sbc.private.ip.address]:5060;branch=z9hG4bK0cB126c28029d093c55 From: <sip:[email protected];pstn-params=9084818088;cpc=ordinary>;tag=gK0c159f6a To: <sip:[email protected]>;tag=gK049472a3 Call-ID: 786540_132020356@[sbc.private.ip.address<mailto:786540_132020356@[sbc.private.ip.address>] CSeq: 286923527 PRACK Max-Forwards: 70 Route: <sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Route: <sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-term> RAck: 2133018667 286923526 INVITE Content-Length: 0 --end msg-- 28-11-2014 07:37:57.804 UTC Debug stack.cpp:465: Queuing cloned received message 0x7fcf640ceb38 for worker threads 28-11-2014 07:37:57.804 UTC Debug stack.cpp:202: Worker thread dequeue message 0x7fcf640ceb38 28-11-2014 07:37:57.804 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg PRACK/cseq=286923527 (rdata0x7fcf640ceb38) 28-11-2014 07:37:57.804 UTC Debug basicproxy.cpp:89: Process PRACK request 28-11-2014 07:37:57.804 UTC Verbose sproutletproxy.cpp:455: Sproutlet Proxy transaction (0x7fcf6c3cd410) created 28-11-2014 07:37:57.804 UTC Debug basicproxy.cpp:1231: Report SAS start marker - trail (1c0ed) 28-11-2014 07:37:57.804 UTC Debug pjutils.cpp:1604: Logging SAS Call-ID marker, Call-ID 786540_132020356@[sbc.private.ip.address<mailto:786540_132020356@[sbc.private.ip.address>] 28-11-2014 07:37:57.804 UTC Debug pjutils.cpp:676: Cloned Request msg PRACK/cseq=286923527 (rdata0x7fcf640ceb38) to tdta0x7fcf6c3d56d0 28-11-2014 07:37:57.804 UTC Debug pjsip: tsx0x7fcf6c477 Transaction created for Request msg PRACK/cseq=286923527 (rdata0x7fcf640ceb38) 28-11-2014 07:37:57.804 UTC Debug pjsip: tsx0x7fcf6c477 Incoming Request msg PRACK/cseq=286923527 (rdata0x7fcf640ceb38) in state Null 28-11-2014 07:37:57.804 UTC Debug pjsip: tsx0x7fcf6c477 State changed from Null to Trying, event=RX_MSG 28-11-2014 07:37:57.804 UTC Debug basicproxy.cpp:214: tsx0x7fcf6c477cd8 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 28-11-2014 07:37:57.804 UTC Debug pjsip: endpoint Response msg 408/PRACK/cseq=286923527 (tdta0x7fcf6c473ef0) created 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:110: Find target Sproutlet for request 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:144: Found next routable URI: sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug scscfsproutlet.cpp:343: S-CSCF Transaction (0x7fcf6c3ceeb0) created 28-11-2014 07:37:57.804 UTC Verbose sproutletproxy.cpp:1006: Created Sproutlet scscf-0x7fcf6c3ceeb0 for Request msg PRACK/cseq=286923527 (tdta0x7fcf6c3d56d0) 28-11-2014 07:37:57.804 UTC Debug pjutils.cpp:693: Cloned tdta0x7fcf6c3d56d0 to tdta0x7fcf6c474f00 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1067: Remove top Route header Route: <sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1500: Adding message 0x7fcf6c475510 => txdata 0x7fcf6c474fa8 mapping 28-11-2014 07:37:57.804 UTC Verbose sproutletproxy.cpp:1380: scscf-0x7fcf6c3ceeb0 pass in dialog request Request msg PRACK/cseq=286923527 (tdta0x7fcf6c474f00) to Sproutlet 28-11-2014 07:37:57.804 UTC Info scscfsproutlet.cpp:440: S-CSCF received in-dialog request 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Info scscfsproutlet.cpp:1445: Charging role is originating 28-11-2014 07:37:57.804 UTC Debug acr.cpp:1466: Create RalfACR for node type S-CSCF with role Originating 28-11-2014 07:37:57.804 UTC Debug acr.cpp:48: Created ACR (0x7fcf6c47e160) 28-11-2014 07:37:57.804 UTC Debug acr.cpp:166: Created S-CSCF Ralf ACR 28-11-2014 07:37:57.804 UTC Debug acr.cpp:205: Set record type for P/S-CSCF 28-11-2014 07:37:57.804 UTC Debug acr.cpp:226: In-dialog PRACK request => INTERIM_RECORD 28-11-2014 07:37:57.804 UTC Debug acr.cpp:1200: Stored 0 subscription identifiers 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1166: Sproutlet send_request 0x7fcf6c475510 28-11-2014 07:37:57.804 UTC Verbose sproutletproxy.cpp:1191: scscf-0x7fcf6c3ceeb0 sending Request msg PRACK/cseq=286923527 (tdta0x7fcf6c474f00) on fork 0 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1515: Processing actions from sproutlet - 0 responses, 1 requests 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1550: Processing request 0x7fcf6c474fa8, fork = 0 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1668: scscf-0x7fcf6c3ceeb0 transmitting request on fork 0 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1682: scscf-0x7fcf6c3ceeb0 store reference to non-ACK request Request msg PRACK/cseq=286923527 (tdta0x7fcf6c474f00) on fork 0 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:1507: Removing message 0x7fcf6c475510 => txdata 0x7fcf6c474fa8 mapping 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:110: Find target Sproutlet for request 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:144: Found next routable URI: sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-term 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.804 UTC Debug scscfsproutlet.cpp:343: S-CSCF Transaction (0x7fcf6c209720) created 28-11-2014 07:37:57.804 UTC Verbose sproutletproxy.cpp:1006: Created Sproutlet scscf-0x7fcf6c209720 for Request msg PRACK/cseq=286923527 (tdta0x7fcf6c474f00) 28-11-2014 07:37:57.805 UTC Debug pjutils.cpp:693: Cloned tdta0x7fcf6c474f00 to tdta0x7fcf6c478b30 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1067: Remove top Route header Route: <sip:ppsprout1.ims.prod.lan:5054;transport=TCP;lr;service=scscf;billing-role=charge-term> 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1500: Adding message 0x7fcf6c479140 => txdata 0x7fcf6c478bd8 mapping 28-11-2014 07:37:57.805 UTC Verbose sproutletproxy.cpp:1380: scscf-0x7fcf6c209720 pass in dialog request Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) to Sproutlet 28-11-2014 07:37:57.805 UTC Info scscfsproutlet.cpp:440: S-CSCF received in-dialog request 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:236: Found services param - scscf 28-11-2014 07:37:57.805 UTC Info scscfsproutlet.cpp:1450: Charging role is terminating 28-11-2014 07:37:57.805 UTC Debug acr.cpp:1466: Create RalfACR for node type S-CSCF with role Terminating 28-11-2014 07:37:57.805 UTC Debug acr.cpp:48: Created ACR (0x7fcf6c327b80) 28-11-2014 07:37:57.805 UTC Debug acr.cpp:166: Created S-CSCF Ralf ACR 28-11-2014 07:37:57.805 UTC Debug acr.cpp:205: Set record type for P/S-CSCF 28-11-2014 07:37:57.805 UTC Debug acr.cpp:226: In-dialog PRACK request => INTERIM_RECORD 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1166: Sproutlet send_request 0x7fcf6c479140 28-11-2014 07:37:57.805 UTC Verbose sproutletproxy.cpp:1191: scscf-0x7fcf6c209720 sending Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) on fork 0 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1515: Processing actions from sproutlet - 0 responses, 1 requests 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1550: Processing request 0x7fcf6c478bd8, fork = 0 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1668: scscf-0x7fcf6c209720 transmitting request on fork 0 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1682: scscf-0x7fcf6c209720 store reference to non-ACK request Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) on fork 0 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:1507: Removing message 0x7fcf6c479140 => txdata 0x7fcf6c478bd8 mapping 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:110: Find target Sproutlet for request 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:144: Found next routable URI: sip:87100004@[sbc.private.ip.address]:5060;rinstance=ebdc3f2d5251207f;dtg=TG_PCSCF_INT_IP 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:262: Found user - 87100004 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:262: Found user - 87100004 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:262: Found user - 87100004 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:262: Found user - 87100004 28-11-2014 07:37:57.805 UTC Debug sproutletproxy.cpp:783: No local sproutlet matches request 28-11-2014 07:37:57.805 UTC Debug pjsip: tsx0x7fcf6c47a Transaction created for Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) 28-11-2014 07:37:57.805 UTC Debug basicproxy.cpp:1586: Added trail identifier 114925 to UAC transaction 28-11-2014 07:37:57.805 UTC Debug pjutils.cpp:505: Next hop node is encoded in Request-URI 28-11-2014 07:37:57.805 UTC Debug sipresolver.cpp:85: SIPResolver::resolve for name [sbc.private.ip.address], port 5060, transport -1, family 2 28-11-2014 07:37:57.805 UTC Debug baseresolver.cpp:511: Attempt to parse [sbc.private.ip.address] as IP address 28-11-2014 07:37:57.805 UTC Debug sipresolver.cpp:102: Target is an IP address - default port/transport if required 28-11-2014 07:37:57.805 UTC Info pjutils.cpp:940: Resolved destination URI sip:87100004@[sbc.private.ip.address]:5060;rinstance=ebdc3f2d5251207f;dtg=TG_PCSCF_INT_IP to 1 servers 28-11-2014 07:37:57.805 UTC Debug basicproxy.cpp:1613: Sending request for sip:87100004@[sbc.private.ip.address]:5060;rinstance=ebdc3f2d5251207f;dtg=TG_PCSCF_INT_IP 28-11-2014 07:37:57.805 UTC Debug pjsip: tsx0x7fcf6c47a Sending Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) in state Null 28-11-2014 07:37:57.805 UTC Debug pjsip: endpoint Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30): skipping target resolution because address is already set 28-11-2014 07:37:57.805 UTC Verbose stack.cpp:255: TX 562 bytes Request msg PRACK/cseq=286923527 (tdta0x7fcf6c478b30) to UDP [sbc.private.ip.address]:5060: --start msg-- PRACK sip:87100004@[sbc.private.ip.address]:5060;rinstance=ebdc3f2d5251207f;dtg=TG_PCSCF_INT_IP SIP/2.0 Via: SIP/2.0/UDP [sprout.network.ip.address]:5052;rport;branch=z9hG4bKPjLuLZfbrxf04GCCv67sHr-sD1433-p4XE Via: SIP/2.0/UDP [sbc.private.ip.address]:5060;received=[sbc.private.ip.address];branch=z9hG4bK0cB126c28029d093c55 From: <sip:[email protected];pstn-params=9084818088;cpc=ordinary>;tag=gK0c159f6a To: <sip:[email protected]>;tag=gK049472a3 Call-ID: 786540_132020356@[sbc.private.ip.address<mailto:786540_132020356@[sbc.private.ip.address>] CSeq: 286923527 PRACK Max-Forwards: 68 RAck: 2133018667 286923526 INVITE Session-Expires: 600 Content-Length: 0 --end msg-- 28-11-2014 07:37:57.805 UTC Debug pjsip: tsx0x7fcf6c47a State changed from Null to Calling, event=TX_MSG 28-11-2014 07:37:57.805 UTC Debug basicproxy.cpp:214: tsx0x7fcf6c47ab98 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 28-11-2014 07:37:57.805 UTC Debug basicproxy.cpp:1769: tsx0x7fcf6c47ab98 - uac_tsx = 0x7fcf6c3d4710, uas_tsx = 0x7fcf6c3cd410 28-11-2014 07:37:57.805 UTC Debug basicproxy.cpp:1777: TX_MSG event on current UAC transaction 28-11-2014 07:37:57.805 UTC Debug stack.cpp:204: Worker thread completed processing message 0x7fcf640ceb38 28-11-2014 07:37:57.805 UTC Debug stack.cpp:210: Request latency = 1340us 28-11-2014 07:37:57.810 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 405/PRACK/cseq=286923527 (rdata0x22f8c48) 28-11-2014 07:37:57.810 UTC Verbose stack.cpp:239: RX 479 bytes Response msg 405/PRACK/cseq=286923527 (rdata0x22f8c48) from UDP [sbc.private.ip.address]:5060: --start msg-- SIP/2.0 405 Method Not Allowed Via: SIP/2.0/UDP [sprout.network.ip.address]:5052;branch=z9hG4bKPjLuLZfbrxf04GCCv67sHr-sD1433-p4XE;rport=5052 Via: SIP/2.0/UDP [sbc.private.ip.address]:5060;received=[sbc.private.ip.address];branch=z9hG4bK0cB126c28029d093c55 From: <sip:[email protected];pstn-params=9084818088;cpc=ordinary>;tag=gK0c159f6a To: <sip:[email protected]>;tag=gK049472a3 Call-ID: 786540_132020356@[sbc.private.ip.address<mailto:786540_132020356@[sbc.private.ip.address>] CSeq: 286923527 PRACK Allow: INVITE,ACK,CANCEL,BYE,REGISTER,OPTIONS Content-Length: 0 2014-11-27 19:52 GMT+01:00 Eleanor Merry <[email protected]<mailto:[email protected]>>: Hi Abaco, I agree with your reading of the scenario. Sprout is just proxying the PRACK, and so should not add any Route headers. If you send me the debug logs from Sprout for the request, then I can take a closer look to see if there's anything else though. 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/*. Ellie -----Original Message----- From: [email protected]<mailto:[email protected]> [mailto:[email protected]<mailto:[email protected]>] On Behalf Of Ruggero Schiavi Sent: 26 November 2014 15:48 To: [email protected]<mailto:[email protected]> Subject: [Clearwater] PRACK PROBLEM I am sorry to bother another time but I am still locked by a prack problem raised with our SBC introduction. Both the calling part and the callee part are attached to the same SBC. The SBC generate the Prack from one side and discarding on the other side. Raised the problem they answered: It seems this might be the issue. Per RFC3261, "12.1.2 UAC Behavior", a snipped text: "The route set MUST be set to the list of URIs in the Record-Route header field from the response, taken in reverse order and preserving all URI parameters." Could you check why S/C-CSCF is not adding Route headers on PRACK? I answered that for me they were wrong in supposing that Sprout should add these route headers. Actually in my opinion the SBC is correctly adding these two headers (and I verified this in their PRACK) and Sprout is performing normal SIP routing mechanism reading the route headers (both sprout orig-term) removing them and finally sending (reading the SIP-URI) to the SBC the Prack for the final destination delivering. So in my opinion it is not a Clearwater problem. They answered again that it is a S-CSCF problem that should add these two headers. Could you give me any hint to clarify this? Am I wrong and therefore it's a bug in Sprout or eventually my reasoning sounds correct? Sprout should add Record-Route header? I understand this may not be a direct problem of Clearwater but if they are right there is something wrong in Sprout (even if I repeat for me Sprout does everything correctly), I look forward for a reply, Thanks a lot, Abaco _______________________________________________ Clearwater mailing list [email protected]<mailto:[email protected]> http://lists.projectclearwater.org/listinfo/clearwater _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
