Hi, Bono rejects the ACK as it’s not part of a trusted flow
14-09-2015 11:21:41.641 UTC Debug bono.cpp:1149: Message received on non-trusted port 5060 14-09-2015 11:21:41.641 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f0c30057018 (2), remote address 137.116.157.180:53924 14-09-2015 11:21:41.641 UTC Info bono.cpp:1339: Rejecting request from untrusted source The ACK isn’t coming from a client that Bono has previously known to be trusted (from a successful register). Do you know why the ACK is coming from a different client (IP:port) than the original INVITE? Ellie From: Clearwater [mailto:[email protected]] On Behalf Of atva angel Sent: 14 September 2015 19:56 To: Clearwater Mail Subject: [Clearwater] Bono does not forward the ACK to Sprout to complete call setup Hi community, I need your help to check my issue because Bono does not forward the ACK to Sprout to complete call setup. - Call model IMS client----OpenSBC----Bono(PCSCF)----Sprout(I/SCSCF, BGCF, integrated External AS)-----SIP Server----SIP client - Scenario 1. IMS client makes call to SIP client 2. SIP client answers - Issue: 1. When SIP client answers, IMS Client sends ACK to Bono but Bono does not forward the ACK to Sprout. Therefore, Sprout does not have ACK to forward to the SIP Server/SIP client to complete call setup - In the debug log on Bono Note: Bono: 137.116.157.173 Sprout: 137.116.157.174 External AS (integrated in Clearwater): 137.116.157.190 OpenSBC: 137.116.157.180 14-09-2015 11:21:41.640 UTC Verbose pjsip: tcplis:5060 TCP listener 137.116.157.173:5060: got incoming TCP connection from 137.116.157.180:53924, sock=136 14-09-2015 11:21:41.640 UTC Verbose pjsip: tcps0x7f0c3005 TCP server transport created 14-09-2015 11:21:41.640 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f0c30057350) 14-09-2015 11:21:41.640 UTC Verbose common_sip_processing.cpp:119: RX 1060 bytes Request msg ACK/cseq=1 (rdata0x7f0c30057350) from TCP 137.116.157.180:53924: --start msg-- ACK sip:137.116.157.190:5060;transport=tcp;nt_end_pt=YM0+~K13kXpz6a05Mtd1t~K5jr0~X7rDXrfrM2~PUDn~Rn2rcevNknice~NC_2SS1y8J+90~EbtYMig~W11MCn9bcf4p6ffSe1bW_P5bfkpzqfQT6MC_h-tnj2~J4S137COd6_153X86c;nt_server_host=137.116.157.190:5060 SIP/2.0 From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 i: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 ACK User-agent: OpenSBC/9.0 Max-Forwards: 70 Allow: ACK,BYE,CANCEL,INVITE,OPTIONS,INFO,SUBSCRIBE,REFER,NOTIFY,PRACK,UPDATE v: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;branch=z9hG4bK-10e7-42081c-14830bfb-aaeb2158 Route: <sip:[email protected]:5060;transport=TCP;lr> Route: <sip:137.116.157.173:5058;transport=TCP;lr> Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Route: <sip:137.116.157.190:5060;lr> m: <sip:[email protected]:5052;transport=TCP> k: resource-priority,timer,path,service-route l: 0 --end msg-- 14-09-2015 11:21:41.640 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 14-09-2015 11:21:41.640 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f0c303e6a78 for worker threads 14-09-2015 11:21:41.640 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f0c303e6a78 14-09-2015 11:21:41.640 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f0c303e6a78) 14-09-2015 11:21:41.640 UTC Debug bono.cpp:255: Proxy RX request 14-09-2015 11:21:41.640 UTC Debug pjutils.cpp:744: Cloned Request msg ACK/cseq=1 (rdata0x7f0c303e6a78) to tdta0x7f0c3405f0f0 14-09-2015 11:21:41.641 UTC Debug bono.cpp:773: Request received on non-trusted port 5060 14-09-2015 11:21:41.641 UTC Debug bono.cpp:1012: Perform access proxy routing for ACK request 14-09-2015 11:21:41.641 UTC Debug pjutils.cpp:580: Found Route header, URI = sip:[email protected]:5060;transport=TCP;lr 14-09-2015 11:21:41.641 UTC Debug pjutils.cpp:583: Route header is local 14-09-2015 11:21:41.641 UTC Debug pjutils.cpp:580: Found Route header, URI = sip:137.116.157.173:5058;transport=TCP;lr 14-09-2015 11:21:41.641 UTC Debug pjutils.cpp:583: Route header is local 14-09-2015 11:21:41.641 UTC Debug bono.cpp:837: Top two route headers added by this node, checking transports and ports 14-09-2015 11:21:41.641 UTC Debug bono.cpp:845: Host names are the same and transports are different 14-09-2015 11:21:41.641 UTC Debug bono.cpp:853: Remove second route header 14-09-2015 11:21:41.641 UTC Debug bono.cpp:1149: Message received on non-trusted port 5060 14-09-2015 11:21:41.641 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f0c30057018 (2), remote address 137.116.157.180:53924 14-09-2015 11:21:41.641 UTC Info bono.cpp:1339: Rejecting request from untrusted source 14-09-2015 11:21:41.641 UTC Debug acr.cpp:1743: Create RalfACR for node type P-CSCF with role Terminating 14-09-2015 11:21:41.641 UTC Debug acr.cpp:49: Created ACR (0x7f0c340056c0) 14-09-2015 11:21:41.641 UTC Debug acr.cpp:171: Created P-CSCF Ralf ACR 14-09-2015 11:21:41.641 UTC Debug acr.cpp:210: Set record type for P/S-CSCF 14-09-2015 11:21:41.641 UTC Debug acr.cpp:231: In-dialog ACK request => INTERIM_RECORD 14-09-2015 11:21:41.641 UTC Verbose acr.cpp:629: Sending P-CSCF Ralf ACR (0x7f0c340056c0) 14-09-2015 11:21:41.641 UTC Debug acr.cpp:656: Building message 14-09-2015 11:21:41.641 UTC Debug acr.cpp:712: Building event 14-09-2015 11:21:41.641 UTC Debug acr.cpp:717: Adding Account-Record-Type AVP 3 14-09-2015 11:21:41.641 UTC Debug acr.cpp:737: Adding Service-Information AVP group 14-09-2015 11:21:41.641 UTC Debug acr.cpp:747: Adding 0 Subscription-Id AVPs 14-09-2015 11:21:41.641 UTC Debug acr.cpp:773: Adding IMS-Information AVP group 14-09-2015 11:21:41.641 UTC Debug acr.cpp:778: Adding Event-Type AVP group 14-09-2015 11:21:41.641 UTC Debug acr.cpp:807: Adding 0 Calling-Party-Address AVPs 14-09-2015 11:21:41.641 UTC Debug acr.cpp:827: Adding Called-Party-Address AVP 14-09-2015 11:21:41.641 UTC Debug acr.cpp:848: Adding 0 Called-Asserted-Identity AVPs 14-09-2015 11:21:41.641 UTC Debug acr.cpp:869: Adding 0 Associated-URI AVPs 14-09-2015 11:21:41.641 UTC Debug acr.cpp:888: Adding Time-Stamps AVP group 14-09-2015 11:21:41.642 UTC Debug acr.cpp:978: Adding 0 Transit-IOI-List AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1077: Adding Media AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1275: Adding SDP-Session-Description AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1082: Adding 0 Message-Body AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1172: Adding 0 Reason-Header AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1190: Adding 0 Access-Network-Information AVPs 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1208: Adding From-Address AVP 14-09-2015 11:21:41.642 UTC Debug acr.cpp:1223: Adding Route-Header-Received AVP 14-09-2015 11:21:41.642 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 137.116.157.177, port 10888, family 2 14-09-2015 11:21:41.642 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.177 as IP address 14-09-2015 11:21:41.642 UTC Debug httpresolver.cpp:79: Target is an IP address 14-09-2015 11:21:41.642 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://137.116.157.177:10888/call-id/b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 (trying 137.116.157.177) on new connection 14-09-2015 11:21:41.643 UTC Debug httpconnection.cpp:896: Received header http/1.1200ok with value 14-09-2015 11:21:41.643 UTC Debug httpconnection.cpp:896: Received header content-length with value 0 14-09-2015 11:21:41.643 UTC Debug httpconnection.cpp:896: Received header with value 14-09-2015 11:21:41.644 UTC Debug httpconnection.cpp:610: Received HTTP response: status=200, doc= 14-09-2015 11:21:41.644 UTC Debug acr.cpp:54: Destroyed ACR (0x7f0c340056c0) 14-09-2015 11:21:41.644 UTC Debug pjsip: tdta0x7f0c3405 Destroying txdata Request msg ACK/cseq=1 (tdta0x7f0c3405f0f0) 14-09-2015 11:21:41.644 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c303e6a78 14-09-2015 11:21:41.644 UTC Debug thread_dispatcher.cpp:199: Request latency = 3678us 14-09-2015 11:21:42.057 UTC Debug pjsip: tsx0x7f0c34066 Timeout timer event 14-09-2015 11:21:42.057 UTC Debug pjsip: tsx0x7f0c34066 State changed from Completed to Terminated, event=TIMER 14-09-2015 11:21:42.057 UTC Debug bono.cpp:359: tsx0x7f0c34066348 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 14-09-2015 11:21:42.057 UTC Debug bono.cpp:2927: tsx0x7f0c34066348 - uac_data = 0x7f0c3406cff0, uas_data = (nil) 14-09-2015 11:21:42.057 UTC Debug pjsip: tsx0x7f0c34066 Timeout timer event 14-09-2015 11:21:42.057 UTC Debug pjsip: tsx0x7f0c34066 State changed from Terminated to Destroyed, event=TIMER 14-09-2015 11:21:42.057 UTC Debug bono.cpp:359: tsx0x7f0c34066348 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 14-09-2015 11:21:42.058 UTC Debug bono.cpp:2927: tsx0x7f0c34066348 - uac_data = 0x7f0c3406cff0, uas_data = (nil) 14-09-2015 11:21:42.058 UTC Debug bono.cpp:3014: tsx0x7f0c34066348 - UAC tsx destroyed Thanks, Tam
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
