Hi community,I need your help to check my issue because Bono does not forward the ACK to Sprout to complete call setup.- Call modelIMS client----OpenSBC----Bono(PCSCF)----Sprout(I/SCSCF, BGCF, integrated External AS)-----SIP Server----SIP client - Scenario1. IMS client makes call to SIP client2. 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 BonoNote:Bono: 137.116.157.173Sprout: 137.116.157.174External AS (integrated in Clearwater): 137.116.157.190OpenSBC: 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
root@ubun1:~# tail -f /var/log/bono/bono_current.txt --end msg-- 14-09-2015 11:21:38.885 UTC Debug common_sip_processing.cpp:253: Skipping SAS logging for OPTIONS response 14-09-2015 11:21:38.885 UTC Debug pjsip: tdta0x7f0c3407 Destroying txdata Response msg 200/OPTIONS/cseq=352420 (tdta0x7f0c3407a8f0) 14-09-2015 11:21:38.885 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c303e5ac8 14-09-2015 11:21:38.885 UTC Debug thread_dispatcher.cpp:199: Request latency = 119us 14-09-2015 11:21:38.885 UTC Info load_monitor.cpp:210: Accepted 100.000000% of requests, latency error = -0.988660, overload responses = 0 14-09-2015 11:21:38.885 UTC Status load_monitor.cpp:237: Maximum incoming request rate/second increased to 19580.843750 (based on a smoothed mean latency of 1134 and 0 upstream overload responses) 14-09-2015 11:21:39.064 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 180/INVITE/cseq=1 (rdata0x7f0c3406ddd0) 14-09-2015 11:21:39.064 UTC Verbose common_sip_processing.cpp:119: RX 1161 bytes Response msg 180/INVITE/cseq=1 (rdata0x7f0c3406ddd0) from TCP 137.116.157.174:5054: --start msg-- SIP/2.0 180 Ringing From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP 137.116.157.173:45364;rport=45364;received=137.116.157.173;branch=z9hG4bKPj2GB2EUALcS6vdcTMbkgWov8OQbrUtLok Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <sip:137.116.157.180:5060;transport=UDP> User-Agent: AppServer 1.0 Supported: resource-priority, timer Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> P-Charging-Vector: icid-value="bbea69bcf46df0f6747f55f7e0e7e125e6287064";icid-generated-at=137.116.157.190 Content-Length: 0 --end msg-- 14-09-2015 11:21:39.064 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 14-09-2015 11:21:39.064 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f0c303e6a78 for worker threads 14-09-2015 11:21:39.064 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f0c303e6a78 14-09-2015 11:21:39.064 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 180/INVITE/cseq=1 (rdata0x7f0c303e6a78) 14-09-2015 11:21:39.064 UTC Debug pjsip: tsx0x7f0c34071 Incoming Response msg 180/INVITE/cseq=1 (rdata0x7f0c303e6a78) in state Proceeding 14-09-2015 11:21:39.064 UTC Debug pjsip: tsx0x7f0c34071 State changed from Proceeding to Proceeding, event=RX_MSG 14-09-2015 11:21:39.065 UTC Debug bono.cpp:359: tsx0x7f0c34071b98 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Proceeding 14-09-2015 11:21:39.065 UTC Debug bono.cpp:2927: tsx0x7f0c34071b98 - uac_data = 0x7f0c34004e00, uas_data = 0x7f0c34062190 14-09-2015 11:21:39.065 UTC Debug bono.cpp:2966: tsx0x7f0c34071b98 - RX_MSG on active UAC transaction 14-09-2015 11:21:39.065 UTC Debug trustboundary.cpp:57: Strip trusted headers 14-09-2015 11:21:39.065 UTC Debug bono.cpp:2145: tsx0x7f0c34071b98 - Forward provisional response on UAS transaction 14-09-2015 11:21:39.065 UTC Debug pjsip: tsx0x7f0c3406d Sending Response msg 180/INVITE/cseq=1 (tdta0x7f0c3407a8f0) in state Proceeding 14-09-2015 11:21:39.065 UTC Debug pjsip: tdta0x7f0c3406 Destroying txdata Response msg 180/INVITE/cseq=1 (tdta0x7f0c34065290) 14-09-2015 11:21:39.065 UTC Verbose common_sip_processing.cpp:135: TX 927 bytes Response msg 180/INVITE/cseq=1 (tdta0x7f0c3407a8f0) to TCP 137.116.157.180:52518: --start msg-- SIP/2.0 180 Ringing From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <sip:137.116.157.180:5060;transport=UDP> User-Agent: AppServer 1.0 Supported: resource-priority, timer Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Content-Length: 0 --end msg-- 14-09-2015 11:21:39.065 UTC Debug pjsip: tsx0x7f0c3406d State changed from Proceeding to Proceeding, event=TX_MSG 14-09-2015 11:21:39.065 UTC Debug bono.cpp:359: tsx0x7f0c3406d308 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Proceeding 14-09-2015 11:21:39.065 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c303e6a78 14-09-2015 11:21:39.065 UTC Debug thread_dispatcher.cpp:199: Request latency = 1001us 14-09-2015 11:21:39.882 UTC Verbose pjsip: tcps0x7f0c3005 TCP connection closed 14-09-2015 11:21:39.883 UTC Debug connection_tracker.cpp:91: Connection 0x7f0c30057018 has been destroyed 14-09-2015 11:21:39.883 UTC Verbose pjsip: tcps0x7f0c3005 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 14-09-2015 11:21:41.634 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) 14-09-2015 11:21:41.634 UTC Verbose common_sip_processing.cpp:119: RX 1674 bytes Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) from TCP 137.116.157.174:5054: --start msg-- SIP/2.0 200 OK From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP 137.116.157.173:45364;rport=45364;received=137.116.157.173;branch=z9hG4bKPj2GB2EUALcS6vdcTMbkgWov8OQbrUtLok Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <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> User-Agent: AppServer 1.0 Supported: resource-priority, timer, replaces Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> P-Charging-Vector: icid-value="bbea69bcf46df0f6747f55f7e0e7e125e6287064";icid-generated-at=137.116.157.190 Session-Expires: 600;refresher=uas Content-Type: application/sdp Content-Length: 231 v=0 o=genband 5742668 5742668 IN IP4 10.250.169.132 s=- [email protected] c=IN IP4 10.250.169.132 t=0 0 m=audio 8308 RTP/AVP 18 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=fmtp:18 annexb=yes a=ptime:20 --end msg-- 14-09-2015 11:21:41.634 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 14-09-2015 11:21:41.634 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f0c30058048 for worker threads 14-09-2015 11:21:41.634 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f0c30058048 14-09-2015 11:21:41.634 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=1 (rdata0x7f0c30058048) 14-09-2015 11:21:41.634 UTC Debug pjsip: tsx0x7f0c34071 Incoming Response msg 200/INVITE/cseq=1 (rdata0x7f0c30058048) in state Proceeding 14-09-2015 11:21:41.634 UTC Debug pjsip: tsx0x7f0c34071 State changed from Proceeding to Terminated, event=RX_MSG 14-09-2015 11:21:41.635 UTC Debug bono.cpp:359: tsx0x7f0c34071b98 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Terminated 14-09-2015 11:21:41.635 UTC Debug bono.cpp:2927: tsx0x7f0c34071b98 - uac_data = 0x7f0c34004e00, uas_data = 0x7f0c34062190 14-09-2015 11:21:41.635 UTC Debug bono.cpp:2966: tsx0x7f0c34071b98 - RX_MSG on active UAC transaction 14-09-2015 11:21:41.635 UTC Debug acr.cpp:1549: Found P-Charging-Vector header, store information 14-09-2015 11:21:41.635 UTC Debug trustboundary.cpp:57: Strip trusted headers 14-09-2015 11:21:41.635 UTC Debug bono.cpp:2152: tsx0x7f0c34071b98 - Final response, so disconnect UAS and UAC transactions 14-09-2015 11:21:41.635 UTC Debug pjsip: tdta0x7f0c3400 Destroying txdata Response msg 408/INVITE/cseq=1 (tdta0x7f0c340008c0) 14-09-2015 11:21:41.635 UTC Debug bono.cpp:2587: Dissociate UAC transaction 0x7f0c34004e00 (0) 14-09-2015 11:21:41.635 UTC Debug pjsip: tsx0x7f0c3406d Sending Response msg 200/INVITE/cseq=1 (tdta0x7f0c34065290) in state Proceeding 14-09-2015 11:21:41.635 UTC Debug pjsip: tdta0x7f0c3407 Destroying txdata Response msg 180/INVITE/cseq=1 (tdta0x7f0c3407a8f0) 14-09-2015 11:21:41.635 UTC Verbose common_sip_processing.cpp:135: TX 1440 bytes Response msg 200/INVITE/cseq=1 (tdta0x7f0c34065290) to TCP 137.116.157.180:52518: --start msg-- SIP/2.0 200 OK From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <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> User-Agent: AppServer 1.0 Supported: resource-priority, timer, replaces Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Session-Expires: 600;refresher=uas Content-Type: application/sdp Content-Length: 231 v=0 o=genband 5742668 5742668 IN IP4 10.250.169.132 s=- [email protected] c=IN IP4 10.250.169.132 t=0 0 m=audio 8308 RTP/AVP 18 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=fmtp:18 annexb=yes a=ptime:20 --end msg-- 14-09-2015 11:21:41.635 UTC Debug pjsip: tsx0x7f0c3406d State changed from Proceeding to Completed, event=TX_MSG 14-09-2015 11:21:41.635 UTC Debug bono.cpp:359: tsx0x7f0c3406d308 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 14-09-2015 11:21:41.635 UTC Debug bono.cpp:773: Request received on non-trusted port 5060 14-09-2015 11:21:41.635 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f0c303de598 (2), remote address 137.116.157.180:52518 14-09-2015 11:21:41.635 UTC Debug flowtable.cpp:599: Dialog count now 2 for flow sip:[email protected] 14-09-2015 11:21:41.635 UTC Debug flowtable.cpp:150: Found flow record 0x7f0c34070690 14-09-2015 11:21:41.635 UTC Debug flowtable.cpp:625: Dialog count now 1 for flow sip:[email protected] 14-09-2015 11:21:41.635 UTC Debug flowtable.cpp:616: Dialog count now 1 for flow sip:[email protected] 14-09-2015 11:21:41.635 UTC Debug bono.cpp:2385: Report SAS end marker - trail (703) 14-09-2015 11:21:41.636 UTC Debug bono.cpp:2284: tsx0x7f0c3406d308 - Terminate UAS INVITE transaction (non-forking case) 14-09-2015 11:21:41.636 UTC Debug pjsip: tsx0x7f0c3406d Request to terminate transaction 14-09-2015 11:21:41.636 UTC Debug pjsip: tsx0x7f0c3406d State changed from Completed to Terminated, event=USER 14-09-2015 11:21:41.636 UTC Debug bono.cpp:359: tsx0x7f0c3406d308 - tu_on_tsx_state UAS, TSX_STATE USER state=Terminated 14-09-2015 11:21:41.636 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c30058048 14-09-2015 11:21:41.636 UTC Debug thread_dispatcher.cpp:199: Request latency = 1617us 14-09-2015 11:21:41.636 UTC Debug pjsip: tsx0x7f0c3406d Timeout timer event 14-09-2015 11:21:41.636 UTC Debug pjsip: tsx0x7f0c3406d State changed from Terminated to Destroyed, event=TIMER 14-09-2015 11:21:41.636 UTC Debug bono.cpp:359: tsx0x7f0c3406d308 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 14-09-2015 11:21:41.636 UTC Debug bono.cpp:2234: tsx0x7f0c3406d308 - UAS tsx destroyed 14-09-2015 11:21:41.636 UTC Debug bono.cpp:2549: tsx0x7f0c3406d308 - Cancel 0 pending UAC transactions 14-09-2015 11:21:41.636 UTC Debug bono.cpp:2558: tsx0x7f0c3406d308 - Check target 0, UAC data = (nil), UAC tsx = (nil) 14-09-2015 11:21:41.636 UTC Debug bono.cpp:1782: UASTransaction destructor (0x7f0c34062190) 14-09-2015 11:21:41.636 UTC Debug bono.cpp:1802: Disconnect UAC transactions from UAS transaction 14-09-2015 11:21:41.636 UTC Debug bono.cpp:1848: Upstream ACR = 0x7f0c340056c0, Downstream ACR = 0x7f0c340056c0 14-09-2015 11:21:41.636 UTC Verbose acr.cpp:629: Sending P-CSCF Ralf ACR (0x7f0c340056c0) 14-09-2015 11:21:41.636 UTC Debug acr.cpp:656: Building message 14-09-2015 11:21:41.636 UTC Debug acr.cpp:673: Adding peers meta-data, 1 ccfs, 0 ecfs 14-09-2015 11:21:41.636 UTC Debug acr.cpp:712: Building event 14-09-2015 11:21:41.636 UTC Debug acr.cpp:717: Adding Account-Record-Type AVP 2 14-09-2015 11:21:41.636 UTC Debug acr.cpp:737: Adding Service-Information AVP group 14-09-2015 11:21:41.636 UTC Debug acr.cpp:747: Adding 1 Subscription-Id AVPs 14-09-2015 11:21:41.636 UTC Debug acr.cpp:773: Adding IMS-Information AVP group 14-09-2015 11:21:41.636 UTC Debug acr.cpp:778: Adding Event-Type AVP group 14-09-2015 11:21:41.636 UTC Debug acr.cpp:807: Adding 1 Calling-Party-Address AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:827: Adding Called-Party-Address AVP 14-09-2015 11:21:41.637 UTC Debug acr.cpp:848: Adding 0 Called-Asserted-Identity AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:869: Adding 0 Associated-URI AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:888: Adding Time-Stamps AVP group 14-09-2015 11:21:41.637 UTC Debug acr.cpp:978: Adding 0 Transit-IOI-List AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1054: Adding 0 Early-Media-Description AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1077: Adding Media AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1275: Adding SDP-Session-Description AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1301: Adding media AVPs for offer 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1308: Adding media AVPs for answer 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1082: Adding 0 Message-Body AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1172: Adding 0 Reason-Header AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1190: Adding 1 Access-Network-Information AVPs 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1208: Adding From-Address AVP 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1223: Adding Route-Header-Received AVP 14-09-2015 11:21:41.637 UTC Debug acr.cpp:1230: Adding Route-Header-Transmitted AVP 14-09-2015 11:21:41.637 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 137.116.157.177, port 10888, family 2 14-09-2015 11:21:41.637 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.177 as IP address 14-09-2015 11:21:41.637 UTC Debug httpresolver.cpp:79: Target is an IP address 14-09-2015 11:21:41.637 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.177 as IP address 14-09-2015 11:21:41.637 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://137.116.157.177:10888/call-id/b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 (trying 137.116.157.177) 14-09-2015 11:21:41.639 UTC Debug httpconnection.cpp:896: Received header http/1.1200ok with value 14-09-2015 11:21:41.639 UTC Debug httpconnection.cpp:896: Received header content-length with value 0 14-09-2015 11:21:41.639 UTC Debug httpconnection.cpp:896: Received header with value 14-09-2015 11:21:41.639 UTC Debug httpconnection.cpp:610: Received HTTP response: status=200, doc= 14-09-2015 11:21:41.639 UTC Debug acr.cpp:54: Destroyed ACR (0x7f0c340056c0) 14-09-2015 11:21:41.639 UTC Debug bono.cpp:1873: Free original request (0x7f0c3405f198) 14-09-2015 11:21:41.639 UTC Debug pjsip: tdta0x7f0c3405 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7f0c3405f0f0) 14-09-2015 11:21:41.639 UTC Debug bono.cpp:1889: UASTransaction destructor completed 14-09-2015 11:21:41.639 UTC Debug pjsip: tdta0x7f0c3406 Destroying txdata Response msg 200/INVITE/cseq=1 (tdta0x7f0c34065290) 14-09-2015 11:21:41.640 UTC Debug pjsip: tsx0x7f0c34071 Timeout timer event 14-09-2015 11:21:41.640 UTC Debug pjsip: tsx0x7f0c34071 State changed from Terminated to Destroyed, event=TIMER 14-09-2015 11:21:41.640 UTC Debug bono.cpp:359: tsx0x7f0c34071b98 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 14-09-2015 11:21:41.640 UTC Debug bono.cpp:2927: tsx0x7f0c34071b98 - uac_data = 0x7f0c34004e00, uas_data = (nil) 14-09-2015 11:21:41.640 UTC Debug bono.cpp:3014: tsx0x7f0c34071b98 - UAC tsx destroyed 14-09-2015 11:21:41.640 UTC Debug pjsip: tdta0x7f0c3400 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7f0c340018d0) 14-09-2015 11:21:41.640 UTC Debug pjsip: tsx0x7f0c3406d Transaction destroyed! 14-09-2015 11:21:41.640 UTC Debug pjsip: tsx0x7f0c34071 Transaction destroyed! 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 14-09-2015 11:21:42.058 UTC Debug pjsip: tdta0x7f0c3407 Destroying txdata Request msg SUBSCRIBE/cseq=18 (tdta0x7f0c34074a90) 14-09-2015 11:21:42.132 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) 14-09-2015 11:21:42.132 UTC Verbose common_sip_processing.cpp:119: RX 1674 bytes Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) from TCP 137.116.157.174:5054: --start msg-- SIP/2.0 200 OK From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP 137.116.157.173:45364;rport=45364;received=137.116.157.173;branch=z9hG4bKPj2GB2EUALcS6vdcTMbkgWov8OQbrUtLok Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <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> User-Agent: AppServer 1.0 Supported: resource-priority, timer, replaces Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> P-Charging-Vector: icid-value="bbea69bcf46df0f6747f55f7e0e7e125e6287064";icid-generated-at=137.116.157.190 Session-Expires: 600;refresher=uas Content-Type: application/sdp Content-Length: 231 v=0 o=genband 5742668 5742668 IN IP4 10.250.169.132 s=- [email protected] c=IN IP4 10.250.169.132 t=0 0 m=audio 8308 RTP/AVP 18 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=fmtp:18 annexb=yes a=ptime:20 --end msg-- 14-09-2015 11:21:42.132 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 14-09-2015 11:21:42.133 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f0c303e6a78 for worker threads 14-09-2015 11:21:42.133 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f0c303e6a78 14-09-2015 11:21:42.133 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/INVITE/cseq=1 (rdata0x7f0c303e6a78) 14-09-2015 11:21:42.133 UTC Debug trustboundary.cpp:168: Strip trusted headers - stateless 14-09-2015 11:21:42.133 UTC Debug trustboundary.cpp:57: Strip trusted headers 14-09-2015 11:21:42.133 UTC Debug pjsip: sip_resolve.c Target '137.116.157.180:5052' type=TCP resolved to '137.116.157.180:5052' type=TCP (TCP transport) 14-09-2015 11:21:42.133 UTC Verbose pjsip: tcpc0x7f0c3406 TCP client transport created 14-09-2015 11:21:42.133 UTC Verbose pjsip: tcpc0x7f0c3406 TCP transport 137.116.157.173:56174 is connecting to 137.116.157.180:5052... 14-09-2015 11:21:42.133 UTC Verbose common_sip_processing.cpp:135: TX 1548 bytes Response msg 200/INVITE/cseq=1 (tdta0x7f0c3405f0f0) to TCP 137.116.157.180:5052: --start msg-- SIP/2.0 200 OK From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <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> User-Agent: AppServer 1.0 Supported: resource-priority, timer, replaces Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> P-Charging-Vector: icid-value="bbea69bcf46df0f6747f55f7e0e7e125e6287064";icid-generated-at=137.116.157.190 Session-Expires: 600;refresher=uas Content-Type: application/sdp Content-Length: 231 v=0 o=genband 5742668 5742668 IN IP4 10.250.169.132 s=- [email protected] c=IN IP4 10.250.169.132 t=0 0 m=audio 8308 RTP/AVP 18 8 101 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=fmtp:18 annexb=yes a=ptime:20 --end msg-- 14-09-2015 11:21:42.134 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c303e6a78 14-09-2015 11:21:42.134 UTC Debug thread_dispatcher.cpp:199: Request latency = 960us 14-09-2015 11:21:42.144 UTC Verbose pjsip: tcpc0x7f0c3406 TCP transport 137.116.157.173:56174 is connected to 137.116.157.180:5052 14-09-2015 11:21:42.144 UTC Debug pjsip: tdta0x7f0c3405 Destroying txdata Response msg 200/INVITE/cseq=1 (tdta0x7f0c3405f0f0) 14-09-2015 11:21:42.154 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f0c30057350) 14-09-2015 11:21:42.154 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:42.155 UTC Debug pjutils.cpp:1707: Logging SAS Call-ID marker, Call-ID b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 14-09-2015 11:21:42.155 UTC Debug thread_dispatcher.cpp:253: Queuing cloned received message 0x7f0c303e7a88 for worker threads 14-09-2015 11:21:42.155 UTC Debug thread_dispatcher.cpp:149: Worker thread dequeue message 0x7f0c303e7a88 14-09-2015 11:21:42.155 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f0c303e7a88) 14-09-2015 11:21:42.155 UTC Debug bono.cpp:255: Proxy RX request 14-09-2015 11:21:42.155 UTC Debug pjutils.cpp:744: Cloned Request msg ACK/cseq=1 (rdata0x7f0c303e7a88) to tdta0x7f0c3405f0f0 14-09-2015 11:21:42.155 UTC Debug bono.cpp:773: Request received on non-trusted port 5060 14-09-2015 11:21:42.155 UTC Debug bono.cpp:1012: Perform access proxy routing for ACK request 14-09-2015 11:21:42.155 UTC Debug pjutils.cpp:580: Found Route header, URI = sip:[email protected]:5060;transport=TCP;lr 14-09-2015 11:21:42.155 UTC Debug pjutils.cpp:583: Route header is local 14-09-2015 11:21:42.155 UTC Debug pjutils.cpp:580: Found Route header, URI = sip:137.116.157.173:5058;transport=TCP;lr 14-09-2015 11:21:42.155 UTC Debug pjutils.cpp:583: Route header is local 14-09-2015 11:21:42.155 UTC Debug bono.cpp:837: Top two route headers added by this node, checking transports and ports 14-09-2015 11:21:42.155 UTC Debug bono.cpp:845: Host names are the same and transports are different 14-09-2015 11:21:42.155 UTC Debug bono.cpp:853: Remove second route header 14-09-2015 11:21:42.155 UTC Debug bono.cpp:1149: Message received on non-trusted port 5060 14-09-2015 11:21:42.155 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f0c30057018 (2), remote address 137.116.157.180:53924 14-09-2015 11:21:42.155 UTC Info bono.cpp:1339: Rejecting request from untrusted source 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1743: Create RalfACR for node type P-CSCF with role Terminating 14-09-2015 11:21:42.156 UTC Debug acr.cpp:49: Created ACR (0x7f0c34003060) 14-09-2015 11:21:42.156 UTC Debug acr.cpp:171: Created P-CSCF Ralf ACR 14-09-2015 11:21:42.156 UTC Debug acr.cpp:210: Set record type for P/S-CSCF 14-09-2015 11:21:42.156 UTC Debug acr.cpp:231: In-dialog ACK request => INTERIM_RECORD 14-09-2015 11:21:42.156 UTC Verbose acr.cpp:629: Sending P-CSCF Ralf ACR (0x7f0c34003060) 14-09-2015 11:21:42.156 UTC Debug acr.cpp:656: Building message 14-09-2015 11:21:42.156 UTC Debug acr.cpp:712: Building event 14-09-2015 11:21:42.156 UTC Debug acr.cpp:717: Adding Account-Record-Type AVP 3 14-09-2015 11:21:42.156 UTC Debug acr.cpp:737: Adding Service-Information AVP group 14-09-2015 11:21:42.156 UTC Debug acr.cpp:747: Adding 0 Subscription-Id AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:773: Adding IMS-Information AVP group 14-09-2015 11:21:42.156 UTC Debug acr.cpp:778: Adding Event-Type AVP group 14-09-2015 11:21:42.156 UTC Debug acr.cpp:807: Adding 0 Calling-Party-Address AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:827: Adding Called-Party-Address AVP 14-09-2015 11:21:42.156 UTC Debug acr.cpp:848: Adding 0 Called-Asserted-Identity AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:869: Adding 0 Associated-URI AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:888: Adding Time-Stamps AVP group 14-09-2015 11:21:42.156 UTC Debug acr.cpp:978: Adding 0 Transit-IOI-List AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1077: Adding Media AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1275: Adding SDP-Session-Description AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1082: Adding 0 Message-Body AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1172: Adding 0 Reason-Header AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1190: Adding 0 Access-Network-Information AVPs 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1208: Adding From-Address AVP 14-09-2015 11:21:42.156 UTC Debug acr.cpp:1223: Adding Route-Header-Received AVP 14-09-2015 11:21:42.156 UTC Debug httpresolver.cpp:71: HttpResolver::resolve for host 137.116.157.177, port 10888, family 2 14-09-2015 11:21:42.156 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.177 as IP address 14-09-2015 11:21:42.156 UTC Debug httpresolver.cpp:79: Target is an IP address 14-09-2015 11:21:42.156 UTC Debug baseresolver.cpp:503: Attempt to parse 137.116.157.177 as IP address 14-09-2015 11:21:42.156 UTC Debug httpconnection.cpp:595: Sending HTTP request : http://137.116.157.177:10888/call-id/b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 (trying 137.116.157.177) 14-09-2015 11:21:42.157 UTC Debug httpconnection.cpp:896: Received header http/1.1200ok with value 14-09-2015 11:21:42.158 UTC Debug httpconnection.cpp:896: Received header content-length with value 0 14-09-2015 11:21:42.158 UTC Debug httpconnection.cpp:896: Received header with value 14-09-2015 11:21:42.158 UTC Debug httpconnection.cpp:610: Received HTTP response: status=200, doc= 14-09-2015 11:21:42.158 UTC Debug acr.cpp:54: Destroyed ACR (0x7f0c34003060) 14-09-2015 11:21:42.158 UTC Debug pjsip: tdta0x7f0c3405 Destroying txdata Request msg ACK/cseq=1 (tdta0x7f0c3405f0f0) 14-09-2015 11:21:42.158 UTC Debug thread_dispatcher.cpp:193: Worker thread completed processing message 0x7f0c303e7a88 14-09-2015 11:21:42.158 UTC Debug thread_dispatcher.cpp:199: Request latency = 3340us 14-09-2015 11:21:42.187 UTC Debug pjsip: tsx0x7f0c34082 Timeout timer event 14-09-2015 11:21:42.187 UTC Debug pjsip: tsx0x7f0c34082 State changed from Completed to Terminated, event=TIMER 14-09-2015 11:21:42.187 UTC Debug bono.cpp:359: tsx0x7f0c340820f8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 14-09-2015 11:21:42.187 UTC Debug bono.cpp:2927: tsx0x7f0c340820f8 - uac_data = 0x7f0c34066de0, uas_data = (nil) 14-09-2015 11:21:42.187 UTC Debug pjsip: tsx0x7f0c34082 Timeout timer event 14-09-2015 11:21:42.187 UTC Debug pjsip: tsx0x7f0c34082 State changed from Terminated to Destroyed, event=TIMER 14-09-2015 11:21:42.187 UTC Debug bono.cpp:359: tsx0x7f0c340820f8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 14-09-2015 11:21:42.188 UTC Debug bono.cpp:2927: tsx0x7f0c340820f8 - uac_data = 0x7f0c34066de0, uas_data = (nil) 14-09-2015 11:21:42.188 UTC Debug bono.cpp:3014: tsx0x7f0c340820f8 - UAC tsx destroyed 14-09-2015 11:21:42.188 UTC Debug pjsip: tdta0x7f0c3408 Destroying txdata Request msg NOTIFY/cseq=902023 (tdta0x7f0c34080090) 14-09-2015 11:21:42.188 UTC Debug pjsip: tsx0x7f0c3407e Transaction destroyed! 14-09-2015 11:21:42.188 UTC Debug pjsip: tsx0x7f0c34082 Transaction destroyed! 14-09-2015 11:21:43.133 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) 14-09-2015 11:21:43.133 UTC Verbose common_sip_processing.cpp:119: RX 1674 bytes Response msg 200/INVITE/cseq=1 (rdata0x7f0c3406ddd0) from TCP 137.116.157.174:5054: --start msg-- SIP/2.0 200 OK From: <sip:1514004152;[email protected];user=phone>;tag=9-13c4-65014-10d0-74746b01-10d0 To: <sip:[email protected];user=phone>;tag=bc9a30722015914182127 Call-ID: b1dda7687099748913c410d041af903cc2e11fe977a8-0062-6880 CSeq: 1 INVITE Via: SIP/2.0/TCP 137.116.157.173:45364;rport=45364;received=137.116.157.173;branch=z9hG4bKPj2GB2EUALcS6vdcTMbkgWov8OQbrUtLok Via: SIP/2.0/TCP OpenSBC:5052;maddr=137.116.157.180;received=137.116.157.180;branch=z9hG4bK-10d0-41af90-53b843f6-aaeb1768 Contact: <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> User-Agent: AppServer 1.0 Supported: resource-priority, timer, replaces Allow: ACK, BYE, CANCEL, INVITE, OPTIONS, INFO, SUBSCRIBE, REFER, NOTIFY, PRACK, UPDATE server: OpenSBC/9.0 Record-Route: <sip:137.116.157.190:5060;lr> Record-Route: <sip:137.116.157.174:5054;transport=TCP;lr;service=scscf;billing-role=charge-orig> Record-Route: <sip:137.116.157.173:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> P-Charging-Vector: icid-value="bbea69bcf46df0f6747f55f7e0e7e125e6287064";icid-generated-at=137.116.157.190 Session-Expires: 600;refresher=uas Content-Type: application/sdp Content-Length: 231
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
