I see the ODI added to the route header by sprout. In this case, the AS is acting as a B2BUA and has independent originating and terminating legs and hence do not carry the route header in the INVITE sent back to sprout. So I made the AS send the INVITE to the trusted sprout port 5054. But then, I guess sprout does the iFC match for the INVITE and send it back to AS and an INVITE loop follows.
I have given the sprout logs below. 23-11-2013 18:44:19.455 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7f206804fe88) 22-11-2013 18:44:19.455 Verbose stack.cpp:199: RX 1323 bytes Request msg INVITE/cseq=1 (rdata0x7f206804fe88) from TCP 10.239.38.59:52304: --start msg-- INVITE sip:[email protected];transport=TCP SIP/2.0 Record-Route: <sip:10.239.38.59:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Via: SIP/2.0/TCP 10.239.38.59:52304;rport;branch=z9hG4bKPj7AwksY6lEZeuPqpu-S3G9GfyAhH.bcik Via: SIP/2.0/TCP 172.15.13.136:46080;rport=46080;received=172.15.13.136;branch=z9hG4bK-d8754z-3f548a899afa22e1-1---d8754z- Max-Forwards: 69 Contact: <sip:[email protected]:46080;transport=TCP> To: <sip:[email protected]> From: <sip:[email protected]>;tag=d4822e78 Call-ID: MTBmZmUwYzY0ZTU3YThhMjU4NmM1MWU4YjY3MWVkOWI. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Zoiper r20066 Allow-Events: presence, kpml P-Asserted-Identity: <sip:[email protected]> Route: <sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054;transport=TCP;lr;orig> Content-Type: application/sdp Content-Length: 261 v=0 o=Zoiper 0 0 IN IP4 172.15.13.136 s=Zoiper c=IN IP4 172.15.13.136 t=0 0 m=audio 33000 RTP/AVP 110 3 0 8 98 a=rtpmap:110 speex/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=30 a=sendrecv --end msg-- 22-11-2013 18:44:19.455 Debug stack.cpp:384: Queuing cloned received message 0x7f206801eb88 for worker threads 22-11-2013 18:44:19.455 Debug stack.cpp:162: Worker thread dequeue message 0x7f206801eb88 22-11-2013 18:44:19.455 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7f206801eb88) 22-11-2013 18:44:19.455 Debug stateful_proxy.cpp:236: Proxy RX request 22-11-2013 18:44:19.455 Debug pjutils.cpp:351: Found Route header, URI = sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054;transport=TCP;lr;orig 22-11-2013 18:44:19.455 Debug stateful_proxy.cpp:466: Got our Route header, session case orig, OD=None 22-11-2013 18:44:19.455 Debug pjutils.cpp:351: Found Route header, URI = sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054;transport=TCP;lr;orig 22-11-2013 18:44:19.455 Debug stateful_proxy.cpp:487: Trust mode TRUSTED(,), serving state orig (new) 22-11-2013 18:44:19.456 Debug pjsip: tsx0x7f2094003 Transaction created for Request msg INVITE/cseq=1 (rdata0x7f206801eb88) 22-11-2013 18:44:19.456 Debug pjsip: tsx0x7f2094003 Incoming Request msg INVITE/cseq=1 (rdata0x7f206801eb88) in state Null 22-11-2013 18:44:19.456 Debug pjsip: tsx0x7f2094003 State changed from Null to Trying, event=RX_MSG 22-11-2013 18:44:19.456 Debug stateful_proxy.cpp:345: tsx0x7f2094003ef8 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 22-11-2013 18:44:19.456 Debug pjsip: endpoint Response msg 408/INVITE/cseq=1 (tdta0x7f2094004770) created 22-11-2013 18:44:19.456 Debug stateful_proxy.cpp:2688: Report SAS start marker - trail (53) 22-11-2013 18:44:19.456 Debug pjsip: endpoint Response msg 100/INVITE/cseq=1 (tdta0x7f2094006940) created 22-11-2013 18:44:19.456 Debug pjsip: tsx0x7f2094003 Sending Response msg 100/INVITE/cseq=1 (tdta0x7f2094006940) in state Trying 22-11-2013 18:44:19.456 Verbose stack.cpp:215: TX 591 bytes Response msg 100/INVITE/cseq=1 (tdta0x7f2094006940) to TCP 10.239.38.59:52304: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.239.38.59:52304;rport=52304;received=10.239.38.59;branch=z9hG4bKPj7AwksY6lEZeuPqpu-S3G9GfyAhH.bcik Via: SIP/2.0/TCP 172.15.13.136:46080;rport=46080;received=172.15.13.136;branch=z9hG4bK-d8754z-3f548a899afa22e1-1---d8754z- Record-Route: <sip:10.239.38.59:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Call-ID: MTBmZmUwYzY0ZTU3YThhMjU4NmM1MWU4YjY3MWVkOWI. From: <sip:[email protected]>;tag=d4822e78 To: <sip:[email protected]> CSeq: 1 INVITE Content-Length: 0 --end msg-- 22-11-2013 18:44:19.456 Debug pjsip: tsx0x7f2094003 State changed from Trying to Proceeding, event=TX_MSG 22-11-2013 18:44:19.456 Debug stateful_proxy.cpp:345: tsx0x7f2094003ef8 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Proceeding 22-11-2013 18:44:19.456 Debug stateful_proxy.cpp:2073: Handle incoming transaction request, serving state = orig (new) 22-11-2013 18:44:19.456 Debug stateful_proxy.cpp:2108: Looking up iFCs for sip:[email protected] for new AS chain 22-11-2013 18:44:19.457 Debug httpconnection.cpp:116: Allocated CURL handle 0x7f209400b890 22-11-2013 18:44:19.457 Debug httpconnection.cpp:235: Sending HTTP request : GET http://localhost:8888/impu/sip%3A6505550985%40example.com (try 0) on new connection 22-11-2013 18:44:19.464 Debug httpconnection.cpp:240: Received HTTP response : <?xml version="1.0" encoding="UTF-8"?> <IMSSubscription xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:noNamespaceSchemaLocation="CxDataType.xsd"><PrivateID>[email protected]</PrivateID><ServiceProfile><InitialFilterCriteria><TriggerPoint><ConditionTypeCNF>0</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension /></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-10-36-11-44.ec2.internal:5080</ServerName><DefaultHandling>0</DefaultHandling></ApplicationServer></InitialFilterCriteria><PublicIdentity><BarringIndication>1</BarringIndication><Identity>sip:[email protected]</Identity></PublicIdentity></ServiceProfile></IMSSubscription> 22-11-2013 18:44:19.464 Debug statistic.cpp:95: Send new value for statistic connected_homesteads, size 2 22-11-2013 18:44:19.464 Debug zmq_lvc.cpp:163: Update to connected_homesteads statistic 22-11-2013 18:44:19.464 Debug zmq_lvc.cpp:246: Clearing message cache for 0x7f2098009cb0 22-11-2013 18:44:19.465 Debug statistic.cpp:95: Send new value for statistic hss_latency_us, size 4 22-11-2013 18:44:19.465 Debug zmq_lvc.cpp:163: Update to hss_latency_us statistic 22-11-2013 18:44:19.465 Debug zmq_lvc.cpp:246: Clearing message cache for 0x7f2098017980 22-11-2013 18:44:19.465 Debug statistic.cpp:95: Send new value for statistic hss_subscription_latency_us, size 4 22-11-2013 18:44:19.465 Debug zmq_lvc.cpp:163: Update to hss_subscription_latency_us statistic 22-11-2013 18:44:19.465 Debug zmq_lvc.cpp:246: Clearing message cache for 0x7f2098020df0 22-11-2013 18:44:19.466 Debug hssconnection.cpp:232: Processing Identity node from HSS XML - sip:[email protected] 22-11-2013 18:44:19.466 Debug memcachedstore.cpp:193: Set up new view 1 for thread 22-11-2013 18:44:19.466 Debug memcachedstore.cpp:202: Setting up server 0 for connection 0x7f2094043080 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --SERVER=10.239.38.59:11211) 22-11-2013 18:44:19.466 Debug memcachedstore.cpp:204: Set up connection 0x7f2094053420 to server 10.239.38.59:11211 22-11-2013 18:44:19.466 Debug memcachedstore.cpp:237: Key sip:[email protected] hashes to vbucket 54 via hash 0x29ad1536 22-11-2013 18:44:19.466 Debug memcachedstore.cpp:277: 1 read replicas for key sip:[email protected] 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:283: Attempt to read from replica 0 (connection 0x7f2094053420) 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:295: Found record on replica 0 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:318: Deserialize record 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:605: There are 1 bindings 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:624: Binding has 0 params 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:638: Binding has 1 paths 22-11-2013 18:44:19.467 Debug memcachedstore.cpp:644: Read path sip:[email protected]:5058;transport=TCP;lr;ob 22-11-2013 18:44:19.467 Debug stateful_proxy.cpp:3764: User sip:[email protected] is registered 22-11-2013 18:44:19.467 Debug aschain.cpp:70: Creating AsChain 0x7f2094057540 and adding to map 22-11-2013 18:44:19.468 Debug stateful_proxy.cpp:3816: Retrieved AsChain AsChain-orig[0x7f2094057540]:1/1 22-11-2013 18:44:19.468 Debug stateful_proxy.cpp:2135: Applying originating services 22-11-2013 18:44:19.468 Debug ifchandler.cpp:247: SPT class Method: result true 22-11-2013 18:44:19.468 Debug ifchandler.cpp:317: Add to group 0 val true 22-11-2013 18:44:19.468 Debug ifchandler.cpp:335: Result group 0 val true 22-11-2013 18:44:19.468 Debug ifchandler.cpp:339: iFC matches 22-11-2013 18:44:19.468 Info ifchandler.cpp:428: Found (triggered) server sip:ip-10-36-11-44.ec2.internal:5080 22-11-2013 18:44:19.468 Info aschain.cpp:235: Invoking external AS sip:ip-10-36-11-44.ec2.internal:5080 with token odi_iwAoYjWDM5 for AsChain-orig[0x7f2094057540]:1/1 22-11-2013 18:44:19.468 Info stateful_proxy.cpp:2152: Originating services disposition 1 22-11-2013 18:44:19.468 Debug stateful_proxy.cpp:2785: Allocating transaction and data for target 0 22-11-2013 18:44:19.469 Debug pjsip: tsx0x7f209405d Transaction created for Request msg INVITE/cseq=1 (tdta0x7f209405bbb0) 22-11-2013 18:44:19.469 Debug stateful_proxy.cpp:2805: Adding trail identifier 83 to UAC transaction 22-11-2013 18:44:19.469 Debug stateful_proxy.cpp:2824: Updating request URI and route for target 0 22-11-2013 18:44:19.469 Debug stateful_proxy.cpp:3204: Adding a Route header to sip:ip-10-36-11-44.ec2.internal 22-11-2013 18:44:19.469 Debug stateful_proxy.cpp:3204: Adding a Route header to sip:[email protected] 22-11-2013 18:44:19.469 Debug stateful_proxy.cpp:3258: Sending request for sip:[email protected];transport=TCP 22-11-2013 18:44:19.469 Debug pjsip: tsx0x7f209405d Sending Request msg INVITE/cseq=1 (tdta0x7f209405bbb0) in state Null 22-11-2013 18:44:19.469 Debug pjsip: sip_resolve.c DNS resolver not available, target 'ip-10-36-11-44.ec2.internal:5080' type=Unspecified will be resolved with getaddrinfo() 22-11-2013 18:44:19.470 Debug pjsip: sip_resolve.c Target 'ip-10-36-11-44.ec2.internal:5080' type=Unspecified resolved to '10.36.11.44:5080' type=UDP (UDP transport) 22-11-2013 18:44:19.470 Debug pjsip: endpoint Request msg INVITE/cseq=1 (tdta0x7f209405bbb0) exceeds UDP size threshold (1300), sending with TCP 22-11-2013 18:44:19.471 Verbose pjsip: tcpc0x7f209406 TCP client transport created 22-11-2013 18:44:19.471 Verbose pjsip: tcpc0x7f209406 TCP transport 10.239.38.59:39188 is connecting to 10.36.11.44:5080... 22-11-2013 18:44:19.471 Verbose stack.cpp:215: TX 1532 bytes Request msg INVITE/cseq=1 (tdta0x7f209405bbb0) to TCP 10.36.11.44:5080: --start msg-- INVITE sip:[email protected];transport=TCP SIP/2.0 Record-Route: <sip:10.239.38.59:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> Via: SIP/2.0/TCP 10.239.38.59:39188;rport;branch=z9hG4bKPjNL3VNxY6uXEZj2xolycO2SytSj8Ovsbd Via: SIP/2.0/TCP 10.239.38.59:52304;rport=52304;received=10.239.38.59;branch=z9hG4bKPj7AwksY6lEZeuPqpu-S3G9GfyAhH.bcik Via: SIP/2.0/TCP 172.15.13.136:46080;rport=46080;received=172.15.13.136;branch=z9hG4bK-d8754z-3f548a899afa22e1-1---d8754z- Max-Forwards: 68 Contact: <sip:[email protected]:46080;transport=TCP> To: <sip:[email protected]> From: <sip:[email protected]>;tag=d4822e78 Call-ID: MTBmZmUwYzY0ZTU3YThhMjU4NmM1MWU4YjY3MWVkOWI. CSeq: 1 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, MESSAGE, OPTIONS, INFO, SUBSCRIBE Supported: replaces, norefersub, extended-refer, timer, X-cisco-serviceuri User-Agent: Zoiper r20066 Allow-Events: presence, kpml P-Asserted-Identity: <sip:[email protected]> P-Served-User: <sip:[email protected]>;sescase=orig;regstate=reg Route: <sip:ip-10-36-11-44.ec2.internal:5080;lr> Route: <sip:[email protected]:5054;lr> Content-Type: application/sdp Content-Length: 261 v=0 o=Zoiper 0 0 IN IP4 172.15.13.136 s=Zoiper c=IN IP4 172.15.13.136 t=0 0 m=audio 33000 RTP/AVP 110 3 0 8 98 a=rtpmap:110 speex/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=30 a=sendrecv --end msg-- 22-11-2013 18:44:19.471 Debug pjsip: tsx0x7f209405d State changed from Null to Calling, event=TX_MSG 22-11-2013 18:44:19.471 Debug stateful_proxy.cpp:345: tsx0x7f209405dc18 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 22-11-2013 18:44:19.471 Debug stateful_proxy.cpp:3336: tsx0x7f209405dc18 - uac_data = 0x7f2094057610, uas_data = 0x7f2094004660 22-11-2013 18:44:19.472 Debug stack.cpp:164: Worker thread completed processing message 0x7f206801eb88 22-11-2013 18:44:19.472 Debug stack.cpp:170: Request latency = 16382us 22-11-2013 18:44:19.481 Verbose pjsip: tcpc0x7f209406 TCP transport 10.239.38.59:39188 is connected to 10.36.11.44:5080 22-11-2013 18:44:19.483 Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=1 (rdata0x7f2094062748) 22-11-2013 18:44:19.483 Verbose stack.cpp:199: RX 767 bytes Response msg 100/INVITE/cseq=1 (rdata0x7f2094062748) from TCP 10.36.11.44:5080: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/TCP 10.239.38.59:39188;rport=39188;branch=z9hG4bKPjNL3VNxY6uXEZj2xolycO2SytSj8Ovsbd Via: SIP/2.0/TCP 10.239.38.59:52304;rport=52304;received=10.239.38.59;branch=z9hG4bKPj7AwksY6lEZeuPqpu-S3G9GfyAhH.bcik Via: SIP/2.0/TCP 172.15.13.136:46080;rport=46080;received=172.15.13.136;branch=z9hG4bK-d8754z-3f548a899afa22e1-1---d8754z- Record-Route: <sip:10.239.38.59:5058;transport=TCP;lr> Record-Route: <sip:[email protected]:5060;transport=TCP;lr> From: <sip:[email protected]>;tag=d4822e78 To: <sip:[email protected]> Call-ID: MTBmZmUwYzY0ZTU3YThhMjU4NmM1MWU4YjY3MWVkOWI. CSeq: 1 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.7b+git~20131118T071121Z~46f5055914~64bit Content-Length: 0 --end msg-- 22-11-2013 18:44:19.483 Debug stack.cpp:384: Queuing cloned received message 0x7f206801eb88 for worker threads 22-11-2013 18:44:19.483 Debug stack.cpp:162: Worker thread dequeue message 0x7f206801eb88 22-11-2013 18:44:19.484 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=1 (rdata0x7f206801eb88) 22-11-2013 18:44:19.484 Debug pjsip: tsx0x7f209405d Incoming Response msg 100/INVITE/cseq=1 (rdata0x7f206801eb88) in state Calling 22-11-2013 18:44:19.484 Debug pjsip: tsx0x7f209405d State changed from Calling to Proceeding, event=RX_MSG 22-11-2013 18:44:19.484 Debug stateful_proxy.cpp:345: tsx0x7f209405dc18 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Proceeding 22-11-2013 18:44:19.484 Debug stateful_proxy.cpp:3336: tsx0x7f209405dc18 - uac_data = 0x7f2094057610, uas_data = 0x7f2094004660 22-11-2013 18:44:19.484 Debug stateful_proxy.cpp:3340: tsx0x7f209405dc18 - RX_MSG on active UAC transaction 22-11-2013 18:44:19.484 Debug stateful_proxy.cpp:2288: tsx0x7f209405dc18 - Discard 100/INVITE response 22-11-2013 18:44:19.484 Debug stack.cpp:164: Worker thread completed processing message 0x7f206801eb88 22-11-2013 18:44:19.484 Debug stack.cpp:170: Request latency = 995us 22-11-2013 18:44:19.508 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=52236864 (rdata0x1484a58) 22-11-2013 18:44:19.508 Verbose stack.cpp:199: RX 1143 bytes Request msg INVITE/cseq=52236864 (rdata0x1484a58) from UDP 10.36.11.44:5080: --start msg-- INVITE sip:[email protected] SIP/2.0 Via: SIP/2.0/UDP 10.36.11.44:5080;rport;branch=z9hG4bKapSDN89yZ7e3j Route: <sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054> Max-Forwards: 67 From: "6505550985" <sip:[email protected]>;tag=1Q6657mX1r50m To: <sip:[email protected]> Call-ID: ee0d4a55-ce48-1231-aa93-12313d251cde CSeq: 52236864 INVITE Contact: <sip:[email protected]:5080> User-Agent: FreeSWITCH-mod_sofia/1.5.7b+git~20131118T071121Z~46f5055914~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 203 P-Served-User: <sip:[email protected]>;sescase=orig;regstate=reg X-FS-Support: update_display,send_info P-Asserted-Identity: "6505550985" <sip:[email protected]> v=0 o=FreeSWITCH 1385123648 1385123649 IN IP4 10.36.11.44 s=FreeSWITCH c=IN IP4 10.36.11.44 t=0 0 m=audio 22208 RTP/AVP 3 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 --end msg-- 22-11-2013 18:44:19.509 Debug stack.cpp:384: Queuing cloned received message 0x7f206801eb88 for worker threads 22-11-2013 18:44:19.509 Debug stack.cpp:162: Worker thread dequeue message 0x7f206801eb88 22-11-2013 18:44:19.509 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=52236864 (rdata0x7f206801eb88) 22-11-2013 18:44:19.509 Debug stateful_proxy.cpp:236: Proxy RX request 22-11-2013 18:44:19.509 Debug pjutils.cpp:351: Found Route header, URI = sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054 22-11-2013 18:44:19.509 Debug stateful_proxy.cpp:466: Got our Route header, session case term, OD=None 22-11-2013 18:44:19.509 Debug pjutils.cpp:351: Found Route header, URI = sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054 22-11-2013 18:44:19.509 Debug stateful_proxy.cpp:487: Trust mode TRUSTED(,), serving state term (new) 22-11-2013 18:44:19.510 Debug pjsip: tsx0x7f209803c Transaction created for Request msg INVITE/cseq=52236864 (rdata0x7f206801eb88) 22-11-2013 18:44:19.510 Debug pjsip: tsx0x7f209803c Incoming Request msg INVITE/cseq=52236864 (rdata0x7f206801eb88) in state Null 22-11-2013 18:44:19.510 Debug pjsip: tsx0x7f209803c State changed from Null to Trying, event=RX_MSG 22-11-2013 18:44:19.510 Debug stateful_proxy.cpp:345: tsx0x7f209803c668 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 22-11-2013 18:44:19.510 Debug pjsip: endpoint Response msg 408/INVITE/cseq=52236864 (tdta0x7f209803d0f0) created 22-11-2013 18:44:19.510 Debug stateful_proxy.cpp:2688: Report SAS start marker - trail (54) 22-11-2013 18:44:19.510 Debug pjsip: endpoint Response msg 100/INVITE/cseq=52236864 (tdta0x7f209803e310) created 22-11-2013 18:44:19.510 Debug pjsip: tsx0x7f209803c Sending Response msg 100/INVITE/cseq=52236864 (tdta0x7f209803e310) in state Trying 22-11-2013 18:44:19.511 Verbose stack.cpp:215: TX 308 bytes Response msg 100/INVITE/cseq=52236864 (tdta0x7f209803e310) to UDP 10.36.11.44:5080: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.36.11.44:5080;rport=5080;received=10.36.11.44;branch=z9hG4bKapSDN89yZ7e3j Call-ID: ee0d4a55-ce48-1231-aa93-12313d251cde From: "6505550985" <sip:[email protected]>;tag=1Q6657mX1r50m To: <sip:[email protected]> CSeq: 52236864 INVITE Content-Length: 0 --end msg-- 22-11-2013 18:44:19.511 Debug pjsip: tsx0x7f209803c State changed from Trying to Proceeding, event=TX_MSG 22-11-2013 18:44:19.511 Debug stateful_proxy.cpp:345: tsx0x7f209803c668 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Proceeding 22-11-2013 18:44:19.511 Debug stateful_proxy.cpp:2073: Handle incoming transaction request, serving state = term (new) 22-11-2013 18:44:19.511 Debug stateful_proxy.cpp:2108: Looking up iFCs for sip:[email protected] for new AS chain 22-11-2013 18:44:19.512 Debug httpconnection.cpp:116: Allocated CURL handle 0x7f2098042270 22-11-2013 18:44:19.512 Debug httpconnection.cpp:235: Sending HTTP request : GET http://localhost:8888/impu/sip%3A6505550793%40example.com (try 0) on new connection 22-11-2013 18:44:19.517 Debug httpconnection.cpp:240: Received HTTP response : <?xml version="1.0" encoding="UTF-8"?> <IMSSubscription xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"; xsi:noNamespaceSchemaLocation="CxDataType.xsd"><PrivateID>[email protected]</PrivateID><ServiceProfile><InitialFilterCriteria><TriggerPoint><ConditionTypeCNF>0</ConditionTypeCNF><SPT><ConditionNegated>0</ConditionNegated><Group>0</Group><Method>INVITE</Method><Extension /></SPT></TriggerPoint><ApplicationServer><ServerName>sip:ip-10-36-11-44.ec2.internal:5080</ServerName><DefaultHandling>0</DefaultHandling></ApplicationServer></InitialFilterCriteria><PublicIdentity><BarringIndication>1</BarringIndication><Identity>sip:[email protected]</Identity></PublicIdentity></ServiceProfile></IMSSubscription> 22-11-2013 18:44:19.517 Debug statistic.cpp:95: Send new value for statistic connected_homesteads, size 2 22-11-2013 18:44:19.517 Debug zmq_lvc.cpp:163: Update to connected_homesteads statistic 22-11-2013 18:44:19.517 Debug zmq_lvc.cpp:246: Clearing message cache for 0x7f2098009cb0 22-11-2013 18:44:19.517 Debug hssconnection.cpp:232: Processing Identity node from HSS XML - sip:[email protected] 22-11-2013 18:44:19.517 Debug memcachedstore.cpp:193: Set up new view 1 for thread 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:202: Setting up server 0 for connection 0x7f2098042210 (--CONNECT-TIMEOUT=10 --SUPPORT-CAS --SERVER=10.239.38.59:11211) 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:204: Set up connection 0x7f2098079950 to server 10.239.38.59:11211 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:237: Key sip:[email protected] hashes to vbucket 1 via hash 0xe2f73e01 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:277: 1 read replicas for key sip:[email protected] 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:283: Attempt to read from replica 0 (connection 0x7f2098079950) 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:295: Found record on replica 0 22-11-2013 18:44:19.518 Debug memcachedstore.cpp:318: Deserialize record 22-11-2013 18:44:19.519 Debug memcachedstore.cpp:605: There are 1 bindings 22-11-2013 18:44:19.519 Debug memcachedstore.cpp:624: Binding has 0 params 22-11-2013 18:44:19.519 Debug memcachedstore.cpp:638: Binding has 1 paths 22-11-2013 18:44:19.519 Debug memcachedstore.cpp:644: Read path sip:[email protected]:5058;transport=TCP;lr;ob 22-11-2013 18:44:19.519 Debug stateful_proxy.cpp:3764: User sip:[email protected] is registered 22-11-2013 18:44:19.519 Debug aschain.cpp:70: Creating AsChain 0x7f209808dcf0 and adding to map 22-11-2013 18:44:19.519 Debug stateful_proxy.cpp:3816: Retrieved AsChain AsChain-term[0x7f209808dcf0]:1/1 22-11-2013 18:44:19.519 Debug stateful_proxy.cpp:2044: Terminating half 22-11-2013 18:44:19.519 Debug stateful_proxy.cpp:2209: Apply terminating services 22-11-2013 18:44:19.519 Debug ifchandler.cpp:247: SPT class Method: result true 22-11-2013 18:44:19.520 Debug ifchandler.cpp:317: Add to group 0 val true 22-11-2013 18:44:19.520 Debug ifchandler.cpp:335: Result group 0 val true 22-11-2013 18:44:19.520 Debug ifchandler.cpp:339: iFC matches 22-11-2013 18:44:19.520 Info ifchandler.cpp:428: Found (triggered) server sip:ip-10-36-11-44.ec2.internal:5080 22-11-2013 18:44:19.520 Info aschain.cpp:235: Invoking external AS sip:ip-10-36-11-44.ec2.internal:5080 with token odi_bOCUiH/18Y for AsChain-term[0x7f209808dcf0]:1/1 22-11-2013 18:44:19.520 Info stateful_proxy.cpp:2228: Terminating services disposition 1 22-11-2013 18:44:19.520 Debug stateful_proxy.cpp:2785: Allocating transaction and data for target 0 22-11-2013 18:44:19.520 Debug pjsip: tsx0x7f2098095 Transaction created for Request msg INVITE/cseq=52236864 (tdta0x7f2098093270) 22-11-2013 18:44:19.520 Debug stateful_proxy.cpp:2805: Adding trail identifier 84 to UAC transaction 22-11-2013 18:44:19.520 Debug stateful_proxy.cpp:2824: Updating request URI and route for target 0 22-11-2013 18:44:19.521 Debug stateful_proxy.cpp:3204: Adding a Route header to sip:ip-10-36-11-44.ec2.internal 22-11-2013 18:44:19.521 Debug stateful_proxy.cpp:3204: Adding a Route header to sip:odi_bOCUiH/[email protected] 22-11-2013 18:44:19.521 Debug stateful_proxy.cpp:3258: Sending request for sip:[email protected] 22-11-2013 18:44:19.521 Debug pjsip: tsx0x7f2098095 Sending Request msg INVITE/cseq=52236864 (tdta0x7f2098093270) in state Null 22-11-2013 18:44:19.521 Debug pjsip: sip_resolve.c DNS resolver not available, target 'ip-10-36-11-44.ec2.internal:5080' type=Unspecified will be resolved with getaddrinfo() 22-11-2013 18:44:19.521 Debug pjsip: sip_resolve.c Target 'ip-10-36-11-44.ec2.internal:5080' type=Unspecified resolved to '10.36.11.44:5080' type=UDP (UDP transport) 22-11-2013 18:44:19.521 Verbose stack.cpp:215: TX 1302 bytes Request msg INVITE/cseq=52236864 (tdta0x7f2098093270) to UDP 10.36.11.44:5080: --start msg-- INVITE sip:[email protected] SIP/2.0 Via: SIP/2.0/UDP 10.239.38.59:5054;rport;branch=z9hG4bKPjG72NR2zFhCRJ0GlB5rDBYBP8gSAI8ex4 Via: SIP/2.0/UDP 10.36.11.44:5080;rport=5080;received=10.36.11.44;branch=z9hG4bKapSDN89yZ7e3j Max-Forwards: 66 From: "6505550985" <sip:[email protected]>;tag=1Q6657mX1r50m To: <sip:[email protected]> Call-ID: ee0d4a55-ce48-1231-aa93-12313d251cde CSeq: 52236864 INVITE Contact: <sip:[email protected]:5080> User-Agent: FreeSWITCH-mod_sofia/1.5.7b+git~20131118T071121Z~46f5055914~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Disposition: session X-FS-Support: update_display,send_info P-Asserted-Identity: "6505550985" <sip:[email protected]> P-Served-User: <sip:[email protected]>;sescase=term;regstate=reg Route: <sip:ip-10-36-11-44.ec2.internal:5080;lr> Route: <sip:odi_bOCUiH/[email protected]:5054;lr> Content-Type: application/sdp Content-Length: 203 v=0 o=FreeSWITCH 1385123648 1385123649 IN IP4 10.36.11.44 s=FreeSWITCH c=IN IP4 10.36.11.44 t=0 0 m=audio 22208 RTP/AVP 3 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 --end msg-- 22-11-2013 18:44:19.522 Debug pjsip: tsx0x7f2098095 State changed from Null to Calling, event=TX_MSG 22-11-2013 18:44:19.522 Debug stateful_proxy.cpp:345: tsx0x7f20980952d8 - tu_on_tsx_state UAC, TSX_STATE TX_MSG state=Calling 22-11-2013 18:44:19.522 Debug stateful_proxy.cpp:3336: tsx0x7f20980952d8 - uac_data = 0x7f209808dab0, uas_data = 0x7f209803cfe0 22-11-2013 18:44:19.522 Debug stack.cpp:164: Worker thread completed processing message 0x7f206801eb88 22-11-2013 18:44:19.522 Debug stack.cpp:170: Request latency = 13439us 22-11-2013 18:44:19.524 Debug pjsip: sip_endpoint.c Processing incoming message: Response msg 100/INVITE/cseq=52236864 (rdata0x1488958) 22-11-2013 18:44:19.524 Verbose stack.cpp:199: RX 482 bytes Response msg 100/INVITE/cseq=52236864 (rdata0x1488958) from UDP 10.36.11.44:5080: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.239.38.59:5054;rport=5054;branch=z9hG4bKPjG72NR2zFhCRJ0GlB5rDBYBP8gSAI8ex4 Via: SIP/2.0/UDP 10.36.11.44:5080;rport=5080;received=10.36.11.44;branch=z9hG4bKapSDN89yZ7e3j From: "6505550985" <sip:[email protected]>;tag=1Q6657mX1r50m To: <sip:[email protected]> Call-ID: ee0d4a55-ce48-1231-aa93-12313d251cde CSeq: 52236864 INVITE User-Agent: FreeSWITCH-mod_sofia/1.5.7b+git~20131118T071121Z~46f5055914~64bit Content-Length: 0 --end msg-- 22-11-2013 18:44:19.524 Debug stack.cpp:384: Queuing cloned received message 0x7f206801eb88 for worker threads 22-11-2013 18:44:19.524 Debug stack.cpp:162: Worker thread dequeue message 0x7f206801eb88 22-11-2013 18:44:19.524 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=52236864 (rdata0x7f206801eb88) 22-11-2013 18:44:19.524 Debug pjsip: tsx0x7f2098095 Incoming Response msg 100/INVITE/cseq=52236864 (rdata0x7f206801eb88) in state Calling 22-11-2013 18:44:19.524 Debug pjsip: tsx0x7f2098095 State changed from Calling to Proceeding, event=RX_MSG 22-11-2013 18:44:19.525 Debug stateful_proxy.cpp:345: tsx0x7f20980952d8 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Proceeding 22-11-2013 18:44:19.525 Debug stateful_proxy.cpp:3336: tsx0x7f20980952d8 - uac_data = 0x7f209808dab0, uas_data = 0x7f209803cfe0 22-11-2013 18:44:19.525 Debug stateful_proxy.cpp:3340: tsx0x7f20980952d8 - RX_MSG on active UAC transaction 22-11-2013 18:44:19.525 Debug stateful_proxy.cpp:2288: tsx0x7f20980952d8 - Discard 100/INVITE response 22-11-2013 18:44:19.525 Debug stack.cpp:164: Worker thread completed processing message 0x7f206801eb88 22-11-2013 18:44:19.525 Debug stack.cpp:170: Request latency = 1012us 22-11-2013 18:44:19.548 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=52236864 (rdata0x148c858) 22-11-2013 18:44:19.548 Verbose stack.cpp:199: RX 1143 bytes Request msg INVITE/cseq=52236864 (rdata0x148c858) from UDP 10.36.11.44:5080: --start msg-- INVITE sip:[email protected] SIP/2.0 Via: SIP/2.0/UDP 10.36.11.44:5080;rport;branch=z9hG4bKBZj6p3t2vg5Ne Route: <sip:ec2-50-17-60-182.compute-1.amazonaws.com:5054> Max-Forwards: 65 From: "6505550985" <sip:[email protected]>;tag=39rr9Xp4Uaj6B To: <sip:[email protected]> Call-ID: ee13762c-ce48-1231-aa93-12313d251cde CSeq: 52236864 INVITE Contact: <sip:[email protected]:5080> User-Agent: FreeSWITCH-mod_sofia/1.5.7b+git~20131118T071121Z~46f5055914~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY Supported: timer, precondition, path, replaces Allow-Events: talk, hold, conference, refer Privacy: none Content-Type: application/sdp Content-Disposition: session Content-Length: 203 P-Served-User: <sip:[email protected]>;sescase=term;regstate=reg X-FS-Support: update_display,send_info P-Asserted-Identity: "6505550985" <sip:[email protected]> v=0 o=FreeSWITCH 1385120808 1385120809 IN IP4 10.36.11.44 s=FreeSWITCH c=IN IP4 10.36.11.44 t=0 0 m=audio 25048 RTP/AVP 3 0 8 101 13 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 --end msg-- -----Original Message----- From: Matt Williams [mailto:[email protected]] Sent: Friday, 22 November 2013 1:27 AM To: Thomas Titty Cc: [email protected] Subject: RE: SIP OPTIONS not forwarded at Bono On Fri, Nov 22, 2013 at 00:27:29, Thomas Titty wrote: > Subject: RE: SIP OPTIONS not forwarded at Bono > > Thanks a lot Matt. I had made the two domain names same. Now I > reverted the deployment name to example.com and SIP OPTIONS are > forwarded between the SIP clients. Great news! > Now, I am able to make the SIP INVITE reach the application server, > but the INVITE request back from the AS is rejected at bono due to > > " 22-11-2013 00:15:43.364 Warning stateful_proxy.cpp:1186: Rejecting > request from untrusted source" and SIP/2.0 403 Forbidden. Bono and sprout expose SIP on multiple ports. Bono exposes two ports: 5060 (untrusted) and 5058 (trusted). Sprout exposes one port: 5054 (trusted). >From the logs you attached, it looks as though the AS is receiving the request >from sprout but sending it back to bono on port 5060. Port 5060 is untrusted >and so expects flows to be authenticated - REGISTERs are challenged but other >SIP methods are simply rejected. When sprout send the INVITE to the AS, it should have included a Route header specifying that the INVITE should be routed back to sprout. The sprout logs would show whether or not this is the case. If the AS is continuing processing on the original call, it should use this Route header. (The Route header also includes an Original Dialog Identifier (ODI) token that allows sprout to correlate the incoming INVITE from the AS back to the INVITE it sent out to the AS.) Alternatively, the AS might want to set up independent calls. For example, a conference server outdial might operate like this. In this case, the AS should send directly to sprout port 5054. Please can you check the Route headers sprout sent to the AS and the logic the AS uses to build the Route headers on the INVITE it sends back? As above, the sprout logs will show the Route headers sent out to the AS. Please let me know how you get on. Thanks, Matt _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
