Hi Roger, In the flows below, your client registered from 10.237.15.136:36754, but sent the INVITE from 10.237.15.136:58560. Bono tracks its connections in a “flowtable”, but it doesn’t know anything about 10.237.15.136:58560, and so it rejects the INVITE with a 403. Similarly, when your client was being called, Bono found a flow token in the Route header but couldn’t match it to anything in its flowtable, presumably because your client had torn down its TCP connection. In short, I’m afraid Bono relies on your clients maintaining their TCP connection after registering. Perimeta, which is a more fully featured P-CSCF, does better here (although it’s worth noting that if for example your client is behind a NAT then there’s not much the P-CSCF can do if the client tears down its TCP connection!).
Thanks! Graeme From: Clearwater [mailto:[email protected]] On Behalf Of Roger Case Sent: 11 January 2018 21:48 To: [email protected] Subject: Re: [Project Clearwater] Bono Send Invite using TCP, Header Reduction Hi Ying, And here is the debug log when the UE (Arris eDVA) on 6505550745 attempts an outgoing call. Registration debug follows below. Thanks! Roger 11-01-2018 21:16:01.038 UTC Verbose pjsip: tcplis:5060 TCP listener cw-aio:5060: got incoming TCP connection from 10.237.15.136:58560, sock=148 11-01-2018 21:16:01.038 UTC Verbose pjsip: tcps0x7f36e010 tcp->base.local_name: cw-aio 11-01-2018 21:16:01.038 UTC Verbose pjsip: tcps0x7f36e010 TCP server transport created 11-01-2018 21:16:01.055 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f36e0105c00) 11-01-2018 21:16:01.055 UTC Verbose common_sip_processing.cpp:120: RX 1168 bytes Request msg INVITE/cseq=1 (rdata0x7f36e0105c00) from TCP 10.237.15.136:58560: --start msg-- INVITE sip:[email protected];user=phone SIP/2.0 From: <sip:[email protected]:5060>;tag=472618-aed0f88-13c4-50029-5a575562-15aaac23-5a575562 To: <sip:[email protected];user=phone> Call-ID: 475b38-aed0f88-13c4-50029-5a575562-fdab92d-5a575562 CSeq: 1 INVITE Via: SIP/2.0/TCP 10.237.15.136:5060;branch=z9hG4bK-5a575562-e525889c-1f65b70 P-Preferred-Identity: <sip:[email protected];user=phone> Max-Forwards: 70 Supported: timer,replaces,join,tdialog,100rel,histinfo,path User-Agent: ARRIS-TM822G release v.9.1.103S5P.SIP.PC20 SN/001DD5F31A69 Contact: <sip:[email protected]:5060;user=phone> Session-Expires: 1800;refresher=uac Min-SE: 90 Allow: INVITE,ACK,BYE,CANCEL,NOTIFY,PRACK,UPDATE,OPTIONS Route: <sip:10.237.20.101:5060> Route: <sip:scscf.cw-aio:5054;transport=TCP;lr;orig> Content-Type: application/sdp Content-Length: 294 v=0 o=- 103984729 103984729 IN IP4 10.237.15.136 s=- c=IN IP4 10.237.15.136 t=0 0 m=audio 52646 RTP/AVP 9 0 8 101 b=AS:80 b=TIAS:64000 a=ptime:20 a=sendrecv a=rtpmap:101 telephone-event/16000 a=fmtp:101 0-15 a=maxprate:50 a=rtcp-xr:voip-metrics a=sqn:0 a=cdsc:1 image udptl t38 --end msg-- 11-01-2018 21:16:01.055 UTC Debug pjutils.cpp:1689: Logging SAS Call-ID marker, Call-ID 475b38-aed0f88-13c4-50029-5a575562-fdab92d-5a575562 11-01-2018 21:16:01.055 UTC Debug thread_dispatcher.cpp:264: Queuing cloned received message 0x7f36e0109118 for worker threads 11-01-2018 21:16:01.055 UTC Debug thread_dispatcher.cpp:150: Worker thread dequeue message 0x7f36e0109118 11-01-2018 21:16:01.055 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f36e0109118) 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:204: Classified URI as 2 11-01-2018 21:16:01.055 UTC Debug bono.cpp:278: Proxy RX request 11-01-2018 21:16:01.055 UTC Debug pjutils.cpp:699: Cloned Request msg INVITE/cseq=1 (rdata0x7f36e0109118) to tdta0x7f36d801f520 11-01-2018 21:16:01.055 UTC Debug bono.cpp:817: Request received on non-trusted port 5060 11-01-2018 21:16:01.055 UTC Debug bono.cpp:1057: Perform access proxy routing for INVITE request 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:174: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:204: Classified URI as 3 11-01-2018 21:16:01.055 UTC Debug pjutils.cpp:509: Found Route header, URI = sip:10.237.20.101:5060 11-01-2018 21:16:01.055 UTC Debug pjutils.cpp:513: Route header is local 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:174: home domain: false, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:16:01.055 UTC Debug uri_classifier.cpp:204: Classified URI as 5 11-01-2018 21:16:01.055 UTC Debug pjutils.cpp:509: Found Route header, URI = sip:scscf.cw-aio:5054;transport=TCP;lr;orig 11-01-2018 21:16:01.055 UTC Debug bono.cpp:1194: Message received on non-trusted port 5060 11-01-2018 21:16:01.055 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f36e01058c8 (2), remote address 10.237.15.136:58560 11-01-2018 21:16:01.055 UTC Info bono.cpp:1384: Rejecting request from untrusted source 11-01-2018 21:16:01.055 UTC Debug acr.cpp:49: Created ACR (0x7f36d8006b30) 11-01-2018 21:16:01.055 UTC Info bono.cpp:771: Reject INVITE request with 403 status code 11-01-2018 21:16:01.056 UTC Debug pjsip: endpoint Response msg 403/INVITE/cseq=1 (tdta0x7f36d8006cb0) created 11-01-2018 21:16:01.056 UTC Verbose common_sip_processing.cpp:136: TX 401 bytes Response msg 403/INVITE/cseq=1 (tdta0x7f36d8006cb0) to TCP 10.237.15.136:58560: --start msg-- SIP/2.0 403 Forbidden Via: SIP/2.0/TCP 10.237.15.136:5060;received=10.237.15.136;branch=z9hG4bK-5a575562-e525889c-1f65b70 Call-ID: 475b38-aed0f88-13c4-50029-5a575562-fdab92d-5a575562 From: <sip:[email protected]>;tag=472618-aed0f88-13c4-50029-5a575562-15aaac23-5a575562 To: <sip:[email protected];user=phone>;tag=z9hG4bK-5a575562-e525889c-1f65b70 CSeq: 1 INVITE Content-Length: 0 --end msg-- 11-01-2018 21:16:01.056 UTC Debug pjsip: tdta0x7f36d800 Destroying txdata Response msg 403/INVITE/cseq=1 (tdta0x7f36d8006cb0) 11-01-2018 21:16:01.056 UTC Debug acr.cpp:83: Sending Null ACR (0x7f36d8006b30) 11-01-2018 21:16:01.056 UTC Debug acr.cpp:54: Destroyed ACR (0x7f36d8006b30) 11-01-2018 21:16:01.056 UTC Debug pjsip: tdta0x7f36d801 Destroying txdata Request msg INVITE/cseq=1 (tdta0x7f36d801f520) 11-01-2018 21:16:01.056 UTC Debug thread_dispatcher.cpp:200: Worker thread completed processing message 0x7f36e0109118 11-01-2018 21:16:01.056 UTC Debug thread_dispatcher.cpp:206: Request latency = 567us 11-01-2018 21:16:01.095 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg ACK/cseq=1 (rdata0x7f36e0105c00) 11-01-2018 21:16:01.095 UTC Verbose common_sip_processing.cpp:120: RX 555 bytes Request msg ACK/cseq=1 (rdata0x7f36e0105c00) from TCP 10.237.15.136:58560: --start msg-- ACK sip:[email protected];user=phone SIP/2.0 From: <sip:[email protected]:5060>;tag=472618-aed0f88-13c4-50029-5a575562-15aaac23-5a575562 To: <sip:[email protected];user=phone>;tag=z9hG4bK-5a575562-e525889c-1f65b70 Call-ID: 475b38-aed0f88-13c4-50029-5a575562-fdab92d-5a575562 CSeq: 1 ACK Via: SIP/2.0/TCP 10.237.15.136:5060;branch=z9hG4bK-5a575562-e525889c-1f65b70 Max-Forwards: 70 User-Agent: ARRIS-TM822G release v.9.1.103S5P.SIP.PC20 SN/001DD5F31A69 Contact: <sip:[email protected]:5060;user=phone> Content-Length: 0 --end msg-- 11-01-2018 21:16:01.095 UTC Debug pjutils.cpp:1689: Logging SAS Call-ID marker, Call-ID 475b38-aed0f88-13c4-50029-5a575562-fdab92d-5a575562 11-01-2018 21:16:01.095 UTC Debug thread_dispatcher.cpp:264: Queuing cloned received message 0x7f36e0108168 for worker threads 11-01-2018 21:16:01.095 UTC Debug thread_dispatcher.cpp:150: Worker thread dequeue message 0x7f36e0108168 11-01-2018 21:16:01.095 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg ACK/cseq=1 (rdata0x7f36e0108168) 11-01-2018 21:16:01.095 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:16:01.095 UTC Debug uri_classifier.cpp:204: Classified URI as 2 11-01-2018 21:16:01.095 UTC Debug bono.cpp:278: Proxy RX request 11-01-2018 21:16:01.095 UTC Debug pjutils.cpp:699: Cloned Request msg ACK/cseq=1 (rdata0x7f36e0108168) to tdta0x7f36d801f520 11-01-2018 21:16:01.095 UTC Debug bono.cpp:817: Request received on non-trusted port 5060 11-01-2018 21:16:01.095 UTC Debug bono.cpp:1057: Perform access proxy routing for ACK request 11-01-2018 21:16:01.095 UTC Debug bono.cpp:1194: Message received on non-trusted port 5060 11-01-2018 21:16:01.095 UTC Debug flowtable.cpp:136: Find flow for transport tcps0x7f36e01058c8 (2), remote address 10.237.15.136:58560 11-01-2018 21:16:01.095 UTC Info bono.cpp:1384: Rejecting request from untrusted source 11-01-2018 21:16:01.095 UTC Debug acr.cpp:49: Created ACR (0x7f36d8006b30) 11-01-2018 21:16:01.096 UTC Debug acr.cpp:83: Sending Null ACR (0x7f36d8006b30) 11-01-2018 21:16:01.096 UTC Debug acr.cpp:54: Destroyed ACR (0x7f36d8006b30) 11-01-2018 21:16:01.096 UTC Debug pjsip: tdta0x7f36d801 Destroying txdata Request msg ACK/cseq=1 (tdta0x7f36d801f520) 11-01-2018 21:16:01.096 UTC Debug thread_dispatcher.cpp:200: Worker thread completed processing message 0x7f36e0108168 11-01-2018 21:16:01.096 UTC Debug thread_dispatcher.cpp:206: Request latency = 394us 11-01-2018 21:16:01.106 UTC Verbose pjsip: tcps0x7f36e010 TCP connection closed 11-01-2018 21:16:01.107 UTC Status connection_tracker.cpp:92: Connection 0x7f36e01058c8 has been destroyed 11-01-2018 21:16:01.107 UTC Verbose pjsip: tcps0x7f36e010 TCP transport destroyed with reason 70016: End of file (PJ_EEOF) 11-01-2018 21:16:01.458 UTC Verbose pjsip: tcps0x7f36e01e TCP connection closed 11-01-2018 21:16:01.458 UTC Status connection_tracker.cpp:92: Connection 0x7f36e01e4ed8 has been destroyed 11-01-2018 21:16:01.458 UTC Verbose pjsip: tcps0x7f36e01e TCP transport destroyed with reason 70016: End of file (PJ_EEOF) ############################## Registration of 6505550745: 11-01-2018 21:28:27.761 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Request msg REGISTER/cseq=1726 (rdata0x7f36e0105c00) 11-01-2018 21:28:27.761 UTC Verbose common_sip_processing.cpp:120: RX 938 bytes Request msg REGISTER/cseq=1726 (rdata0x7f36e0105c00) from TCP 10.237.15.136:36754: --start msg-- REGISTER sip:example.com SIP/2.0 From: <sip:[email protected]:5060>;tag=470ef0-aed0f88-13c4-50029-5a555eb9-40adda66-5a555eb9 To: <sip:[email protected]:5060> Call-ID: 478378-aed0f88-13c4-50029-5a555eb9-3667940-5a555eb9 CSeq: 1726 REGISTER Via: SIP/2.0/TCP 10.237.15.136:5060;branch=z9hG4bK-5a57584d-e530ed72-6696d8d Max-Forwards: 70 Supported: timer,replaces,join,tdialog,100rel,histinfo,path User-Agent: ARRIS-TM822G release v.9.1.103S5P.SIP.PC20 SN/001DD5F31A69 Authorization: Digest username="[email protected]<mailto:[email protected]>",realm="example.com",nonce="7aed3cde60bca4f0",uri="sip:example.com",response="402b48d7a9645a922aca71ac2ca09e7d",algorithm=MD5,cnonce="e530ed72",opaque="6d7a8a5f509faace",qop=auth,nc=00000001 Contact: <sip:[email protected]:5060>;expires=3600 Allow: INVITE,ACK,BYE,CANCEL,NOTIFY,PRACK,UPDATE,OPTIONS Allow-Events: vq-rtcpxr Route: <sip:10.237.20.101;transport=udp;lr> Content-Length: 0 --end msg-- 11-01-2018 21:28:27.761 UTC Debug pjutils.cpp:1689: Logging SAS Call-ID marker, Call-ID 478378-aed0f88-13c4-50029-5a555eb9-3667940-5a555eb9 11-01-2018 21:28:27.761 UTC Debug thread_dispatcher.cpp:264: Queuing cloned received message 0x7f36e0024638 for worker threads 11-01-2018 21:28:27.761 UTC Debug thread_dispatcher.cpp:150: Worker thread dequeue message 0x7f36e0024638 11-01-2018 21:28:27.761 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg REGISTER/cseq=1726 (rdata0x7f36e0024638) 11-01-2018 21:28:27.761 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.761 UTC Debug uri_classifier.cpp:204: Classified URI as 4 11-01-2018 21:28:27.761 UTC Debug bono.cpp:278: Proxy RX request 11-01-2018 21:28:27.762 UTC Debug pjutils.cpp:699: Cloned Request msg REGISTER/cseq=1726 (rdata0x7f36e0024638) to tdta0x7f36d803b360 11-01-2018 21:28:27.762 UTC Debug bono.cpp:817: Request received on non-trusted port 5060 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1057: Perform access proxy routing for REGISTER request 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1094: Message requires outbound support 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:90: Find or create flow for transport tcps0x7f36e01058c8 (2), remote address 10.237.15.136:36754 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:293: Added transport listener for flow 0x7f36d803c990 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:105: Added flow record 0x7f36d803c990 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:232: Reporting current flow count: 7 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:599: Dialog count now 2 for flow 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1106: Found or created flow data record, token = 3ptyUGaJM/ 11-01-2018 21:28:27.762 UTC Info pjutils.cpp:389: Adding integrity-protected=ip-assoc-pending indicator to message 11-01-2018 21:28:27.762 UTC Debug flowtable.cpp:616: Dialog count now 1 for flow 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:204: Classified URI as 4 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:174: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:204: Classified URI as 3 11-01-2018 21:28:27.762 UTC Debug pjutils.cpp:509: Found Route header, URI = sip:10.237.20.101;transport=udp;lr 11-01-2018 21:28:27.762 UTC Debug pjutils.cpp:513: Route header is local 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1015: Mark originating 11-01-2018 21:28:27.762 UTC Info bono.cpp:1036: Route request to upstream proxy sip:scscf.cw-aio:5052;transport=TCP;lr;orig 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:204: Classified URI as 4 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:174: home domain: false, local_to_node: true, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:204: Classified URI as 3 11-01-2018 21:28:27.762 UTC Debug pjutils.cpp:509: Found Route header, URI = sip:10.237.20.101;transport=udp;lr 11-01-2018 21:28:27.762 UTC Debug pjutils.cpp:513: Route header is local 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1604: Top Route header is local - erasing 11-01-2018 21:28:27.762 UTC Debug acr.cpp:49: Created ACR (0x7f36d8006bd0) 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:174: home domain: true, local_to_node: false, is_gruu: false, enforce_user_phone: false, prefer_sip: true, treat_number_as_phone: false 11-01-2018 21:28:27.762 UTC Debug uri_classifier.cpp:204: Classified URI as 4 11-01-2018 21:28:27.762 UTC Debug bono.cpp:486: Trust mode INBOUND_EDGE_CLIENT(,-rsp,-pch), serving state None 11-01-2018 21:28:27.762 UTC Debug pjsip: tsx0x7f36d8089 Transaction created for Request msg REGISTER/cseq=1726 (rdata0x7f36e0024638) 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1786: UASTransaction constructor (0x7f36d8042e20) 11-01-2018 21:28:27.762 UTC Debug bono.cpp:1787: ACR (0x7f36d8006bd0) 11-01-2018 21:28:27.762 UTC Debug pjsip: tsx0x7f36d8089 Incoming Request msg REGISTER/cseq=1726 (rdata0x7f36e0024638) in state Null 11-01-2018 21:28:27.762 UTC Debug pjsip: tsx0x7f36d8089 State changed from Null to Trying, event=RX_MSG 11-01-2018 21:28:27.762 UTC Debug bono.cpp:390: tsx0x7f36d8089098 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 11-01-2018 21:28:27.762 UTC Debug pjsip: endpoint Response msg 408/REGISTER/cseq=1726 (tdta0x7f36d809e880) created 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2418: Report SAS start marker - trail (b6) 11-01-2018 21:28:27.762 UTC Debug trustboundary.cpp:69: Add P-Charging headers 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2492: Allocating transaction and data for target 0 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2749: Stripping loose routes from proxied message 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2776: Adding a Route header to sip:scscf.cw-aio:5052;transport=TCP 11-01-2018 21:28:27.762 UTC Debug pjsip: tsx0x7f36d8037 Transaction created for Request msg REGISTER/cseq=1726 (tdta0x7f36d8027870) 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2519: Adding trail identifier 182 to UAC transaction 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2538: Updating request URI and route for target 0 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2844: Transport tcpc0x7f36d809d098 (TCP to 10.237.20.101:5052) pre-selected for transaction 11-01-2018 21:28:27.762 UTC Debug bono.cpp:2862: Sending request for sip:example.com 11-01-2018 21:28:27.762 UTC Debug pjsip: tsx0x7f36d8037 Sending Request msg REGISTER/cseq=1726 (tdta0x7f36d8027870) in state Null 11-01-2018 21:28:27.762 UTC Debug pjsip: endpoint Request msg REGISTER/cseq=1726 (tdta0x7f36d8027870): skipping target resolution because address is already set 11-01-2018 21:28:27.762 UTC Verbose common_sip_processing.cpp:136: TX 1210 bytes Request msg REGISTER/cseq=1726 (tdta0x7f36d8027870) to TCP 10.237.20.101:5052: --start msg-- REGISTER sip:example.com SIP/2.0 Via: SIP/2.0/TCP 10.237.20.101:5058;rport;branch=z9hG4bKPjY-uiB2yim8VSRPwMd7oV-5M7Zdr4xerU Path: <sip:3ptyUGaJM/@10.237.20.101:5058;transport=TCP;lr;ob> From: <sip:[email protected]>;tag=470ef0-aed0f88-13c4-50029-5a555eb9-40adda66-5a555eb9 To: <sip:[email protected]> Call-ID: 478378-aed0f88-13c4-50029-5a555eb9-3667940-5a555eb9 CSeq: 1726 REGISTER Via: SIP/2.0/TCP 10.237.15.136:5060;received=10.237.15.136;branch=z9hG4bK-5a57584d-e530ed72-6696d8d Max-Forwards: 70 Supported: timer, replaces, join, tdialog, 100rel, histinfo, path User-Agent: ARRIS-TM822G release v.9.1.103S5P.SIP.PC20 SN/001DD5F31A69 Authorization: Digest response="402b48d7a9645a922aca71ac2ca09e7d", username="[email protected]<mailto:[email protected]>", realm="example.com", nonce="7aed3cde60bca4f0", uri="sip:example.com", algorithm=MD5, cnonce="e530ed72", opaque="6d7a8a5f509faace", qop=auth, nc=00000001,integrity-protected=ip-assoc-pending Contact: <sip:[email protected]:5060>;expires=3600 Allow: INVITE, ACK, BYE, CANCEL, NOTIFY, PRACK, UPDATE, OPTIONS Allow-Events: vq-rtcpxr P-Visited-Network-ID: example.com Route: <sip:scscf.cw-aio:5052;transport=TCP;lr;orig> Content-Length: 0 --end msg-- 11-01-2018 21:28:27.764 UTC Debug pjsip: tsx0x7f36d8037 State changed from Null to Calling, event=TX_MSG 11-01-2018 21:28:27.764 UTC Debug bono.cpp:390: tsx0x7f36d8037de8 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 11-01-2018 21:28:27.764 UTC Debug bono.cpp:2962: tsx0x7f36d8037de8 - uac_data = 0x7f36d803cd20, uas_data = 0x7f36d8042e20 11-01-2018 21:28:27.764 UTC Debug thread_dispatcher.cpp:200: Worker thread completed processing message 0x7f36e0024638 11-01-2018 21:28:27.764 UTC Debug thread_dispatcher.cpp:206: Request latency = 2476us 11-01-2018 21:28:27.768 UTC Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 200/REGISTER/cseq=1726 (rdata0x7f36d809d3d0) 11-01-2018 21:28:27.768 UTC Verbose common_sip_processing.cpp:120: RX 787 bytes Response msg 200/REGISTER/cseq=1726 (rdata0x7f36d809d3d0) from TCP 10.237.20.101:5052: --start msg-- SIP/2.0 200 OK Service-Route: <sip:scscf.cw-aio:5054;transport=TCP;lr;orig> Via: SIP/2.0/TCP 10.237.20.101:5058;rport=59420;received=10.237.20.101;branch=z9hG4bKPjY-uiB2yim8VSRPwMd7oV-5M7Zdr4xerU Via: SIP/2.0/TCP 10.237.15.136:5060;received=10.237.15.136;branch=z9hG4bK-5a57584d-e530ed72-6696d8d Call-ID: 478378-aed0f88-13c4-50029-5a555eb9-3667940-5a555eb9 From: <sip:[email protected]>;tag=470ef0-aed0f88-13c4-50029-5a555eb9-40adda66-5a555eb9 To: <sip:[email protected]>;tag=z9hG4bKPjY-uiB2yim8VSRPwMd7oV-5M7Zdr4xerU CSeq: 1726 REGISTER Supported: outbound Contact: <sip:[email protected]:5060>;expires=300 Require: outbound Path: <sip:3ptyUGaJM/@10.237.20.101:5058;transport=TCP;lr;ob> P-Associated-URI: <sip:[email protected]> Content-Length: 0 --end msg-- 11-01-2018 21:28:27.768 UTC Debug thread_dispatcher.cpp:264: Queuing cloned received message 0x7f36e0024638 for worker threads 11-01-2018 21:28:27.768 UTC Debug thread_dispatcher.cpp:150: Worker thread dequeue message 0x7f36e0024638 11-01-2018 21:28:27.768 UTC Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 200/REGISTER/cseq=1726 (rdata0x7f36e0024638) 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 Incoming Response msg 200/REGISTER/cseq=1726 (rdata0x7f36e0024638) in state Calling 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 State changed from Calling to Completed, event=RX_MSG 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8037de8 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Completed 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2962: tsx0x7f36d8037de8 - uac_data = 0x7f36d803cd20, uas_data = 0x7f36d8042e20 11-01-2018 21:28:27.768 UTC Debug bono.cpp:3001: tsx0x7f36d8037de8 - RX_MSG on active UAC transaction 11-01-2018 21:28:27.768 UTC Debug flowtable.cpp:164: Find flow for flow token 3ptyUGaJM/ 11-01-2018 21:28:27.768 UTC Debug flowtable.cpp:599: Dialog count now 2 for flow 11-01-2018 21:28:27.768 UTC Debug flowtable.cpp:177: Found flow record 0x7f36d803c990 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1694: Maximum contact expiry is 300 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1720: Found P-Associated-URI header 11-01-2018 21:28:27.768 UTC Debug flowtable.cpp:413: Setting identity sip:[email protected] on flow 0x7f36d803c990, expires = 300 11-01-2018 21:28:27.768 UTC Debug flowtable.cpp:616: Dialog count now 1 for flow sip:[email protected] 11-01-2018 21:28:27.768 UTC Debug trustboundary.cpp:57: Strip trusted headers 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2194: tsx0x7f36d8037de8 - Final response, so disconnect UAS and UAC transactions 11-01-2018 21:28:27.768 UTC Debug pjsip: tdta0x7f36d809 Destroying txdata Response msg 408/REGISTER/cseq=1726 (tdta0x7f36d809e880) 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2629: Dissociate UAC transaction 0x7f36d803cd20 (0) 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 Sending Response msg 200/REGISTER/cseq=1726 (tdta0x7f36d80296a0) in state Trying 11-01-2018 21:28:27.768 UTC Verbose common_sip_processing.cpp:136: TX 666 bytes Response msg 200/REGISTER/cseq=1726 (tdta0x7f36d80296a0) to TCP 10.237.15.136:36754: --start msg-- SIP/2.0 200 OK Service-Route: <sip:scscf.cw-aio:5054;transport=TCP;lr;orig> Via: SIP/2.0/TCP 10.237.15.136:5060;received=10.237.15.136;branch=z9hG4bK-5a57584d-e530ed72-6696d8d Call-ID: 478378-aed0f88-13c4-50029-5a555eb9-3667940-5a555eb9 From: <sip:[email protected]>;tag=470ef0-aed0f88-13c4-50029-5a555eb9-40adda66-5a555eb9 To: <sip:[email protected]>;tag=z9hG4bKPjY-uiB2yim8VSRPwMd7oV-5M7Zdr4xerU CSeq: 1726 REGISTER Supported: outbound Contact: <sip:[email protected]:5060>;expires=300 Require: outbound Path: <sip:3ptyUGaJM/@10.237.20.101:5058;transport=TCP;lr;ob> P-Associated-URI: <sip:[email protected]> Content-Length: 0 --end msg-- 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 State changed from Trying to Completed, event=TX_MSG 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8089098 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Completed 11-01-2018 21:28:27.768 UTC Debug bono.cpp:817: Request received on non-trusted port 5060 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2427: Report SAS end marker - trail (b6) 11-01-2018 21:28:27.768 UTC Debug thread_dispatcher.cpp:200: Worker thread completed processing message 0x7f36e0024638 11-01-2018 21:28:27.768 UTC Debug thread_dispatcher.cpp:206: Request latency = 281us 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 Timeout timer event 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 State changed from Completed to Terminated, event=TIMER 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8037de8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Terminated 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2962: tsx0x7f36d8037de8 - uac_data = 0x7f36d803cd20, uas_data = (nil) 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 Timeout timer event 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 State changed from Completed to Terminated, event=TIMER 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8089098 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Terminated 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 Timeout timer event 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 State changed from Terminated to Destroyed, event=TIMER 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8037de8 - tu_on_tsx_state UAC, TSX_STATE TIMER state=Destroyed 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2962: tsx0x7f36d8037de8 - uac_data = 0x7f36d803cd20, uas_data = (nil) 11-01-2018 21:28:27.768 UTC Debug bono.cpp:3049: tsx0x7f36d8037de8 - UAC tsx destroyed 11-01-2018 21:28:27.768 UTC Debug pjsip: tdta0x7f36d802 Destroying txdata Request msg REGISTER/cseq=1726 (tdta0x7f36d8027870) 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 Timeout timer event 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 State changed from Terminated to Destroyed, event=TIMER 11-01-2018 21:28:27.768 UTC Debug bono.cpp:390: tsx0x7f36d8089098 - tu_on_tsx_state UAS, TSX_STATE TIMER state=Destroyed 11-01-2018 21:28:27.768 UTC Debug bono.cpp:2276: tsx0x7f36d8089098 - UAS tsx destroyed 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1831: UASTransaction destructor (0x7f36d8042e20) 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1851: Disconnect UAC transactions from UAS transaction 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1897: Upstream ACR = 0x7f36d8006bd0, Downstream ACR = 0x7f36d8006bd0 11-01-2018 21:28:27.768 UTC Debug acr.cpp:83: Sending Null ACR (0x7f36d8006bd0) 11-01-2018 21:28:27.768 UTC Debug acr.cpp:54: Destroyed ACR (0x7f36d8006bd0) 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1922: Free original request (0x7f36d803b408) 11-01-2018 21:28:27.768 UTC Debug pjsip: tdta0x7f36d803 Destroying txdata Request msg REGISTER/cseq=1726 (tdta0x7f36d803b360) 11-01-2018 21:28:27.768 UTC Debug bono.cpp:1938: UASTransaction destructor completed 11-01-2018 21:28:27.768 UTC Debug pjsip: tdta0x7f36d802 Destroying txdata Response msg 200/REGISTER/cseq=1726 (tdta0x7f36d80296a0) 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8089 Transaction destroyed! 11-01-2018 21:28:27.768 UTC Debug pjsip: tsx0x7f36d8037 Transaction destroyed! 11-01-2018 21:28:27.792 UTC Verbose pjsip: tcps0x7f36e010 TCP connection closed 11-01-2018 21:28:27.792 UTC Debug flowtable.cpp:652: Transport state changed for flow 0x7f36d803c990, state = 1 11-01-2018 21:28:27.792 UTC Debug flowtable.cpp:205: Remove flow 0x7f36d803c990 11-01-2018 21:28:27.792 UTC Debug flowtable.cpp:232: Reporting current flow count: 6 11-01-2018 21:28:27.792 UTC Debug flowtable.cpp:197: Checked quiescing state: flow_map is not empty, is_quiescing() result is false, _qm (QuiescingManager reference) is not NULL 11-01-2018 21:28:27.793 UTC Status connection_tracker.cpp:92: Connection 0x7f36e01058c8 has been destroyed 11-01-2018 21:28:27.793 UTC Verbose pjsip: tcps0x7f36e010 TCP transport destroyed with reason 70016: End of file (PJ_EEOF)
_______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/mailman/listinfo/clearwater_lists.projectclearwater.org
