Hi Trey, Thanks for raising this - we're investigating it now.
Ellie -----Original Message----- From: [email protected] [mailto:[email protected]] On Behalf Of Ormsbee, Trey Sent: 10 July 2014 19:40 To: [email protected] Subject: [Clearwater] Sprout stripping sdp of msrp request. I am seeing an issue with sprout removing the sdp of a sip message that was received with an msrp sdp. In this case it is an INVITE that sprout passed on to our application server that includes the sdp, when passed back from the application server the sdp is still there. But when forwarding back out to the recipient the sdp is gone. Nothing in the logs stands out. Here is a sanitized excerpt from the log starting from the received INVITE from the application server.. If needed I can attach more of the log. 10-07-2014 16:44:56.943 Debug stack.cpp:410: Queuing cloned received message 0x7ff93035a8c8 for worker threads 10-07-2014 16:44:56.943 Debug stack.cpp:189: Worker thread dequeue message 0x7ff93035a8c8 10-07-2014 16:44:56.943 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Response msg 100/INVITE/cseq=16363 (rdata0x7ff93035a8c8) 10-07-2014 16:44:56.943 Debug pjsip: tsx0x7ff9202b0 Incoming Response msg 100/INVITE/cseq=16363 (rdata0x7ff93035a8c8) in state Calling 10-07-2014 16:44:56.943 Debug pjsip: tsx0x7ff9202b0 State changed from Calling to Proceeding, event=RX_MSG 10-07-2014 16:44:56.943 Debug stateful_proxy.cpp:365: tsx0x7ff9202b0da8 - tu_on_tsx_state UAC, TSX_STATE RX_MSG state=Proceeding 10-07-2014 16:44:56.943 Debug stateful_proxy.cpp:4295: tsx0x7ff9202b0da8 - uac_data = 0x7ff9202b8fb0, uas_data = 0x7ff92019bd30 10-07-2014 16:44:56.943 Debug stateful_proxy.cpp:4334: tsx0x7ff9202b0da8 - RX_MSG on active UAC transaction 10-07-2014 16:44:56.943 Debug stateful_proxy.cpp:3133: tsx0x7ff9202b0da8 - Discard 100/INVITE response 10-07-2014 16:44:56.943 Debug stack.cpp:191: Worker thread completed processing message 0x7ff93035a8c8 10-07-2014 16:44:56.943 Debug stack.cpp:197: Request latency = 325us 10-07-2014 16:44:56.943 Debug pjsip: sip_endpoint.c Processing incoming message: Request msg INVITE/cseq=1 (rdata0x7ff9300369b8) 10-07-2014 16:44:56.943 Verbose stack.cpp:226: RX 1898 bytes Request msg INVITE/cseq=1 (rdata0x7ff9300369b8) from TCP xxx.xxx.xxx.101:45311: --start msg-- INVITE sip:[email protected];user=phone SIP/2.0 Via: SIP/2.0/TCP xxx.xxx.xxx.101:5510;branch=z9hG4bK97cdab82-dbe2-42a6-92c7-4db45587fa2d From: <sip:[email protected]>;tag=18d3e679-45cd-470b-9bd4-ec43e8dfbf78 To: <sip:[email protected];user=phone> Call-ID: c1855804-1075-4053-9047-b7c869c24ae0 CSeq: 1 INVITE Contact: <sip:[email protected]:5510>;+g.oma.sip-im;+sip.instance="<urn:gsma:imei:35513605-331763-5>" Accept-Contact: *;+g.oma.sip-im Allow: INVITE,ACK,CANCEL,BYE,UPDATE,REFER,SUBSCRIBE,MESSAGE,REGISTER,INFO User-Agent: IM-serv/OMA1.0 CustomEntry-RMS/2.0 Supported: timer,gruu Session-Expires: 400;refresher=uas Min-SE: 400 P-Asserted-Identity: <sip:[email protected]> Subject: Xjckvkvk Contribution-ID: WtNdhjExDY8aqwiQ8ffTo0k4rsnlnI1LsLZD Content-Type: multipart/mixed;boundary="gc0p4Jq0M2Yt08j34c0p" P-Charging-Vector: icid-value="30fdc0efc89051a5a2de485d92166e5a";orig-ioi=example.com Content-Length: 896 Max-Forwards: 70 --gc0p4Jq0M2Yt08j34c0p Content-Type: message/cpim From: <sip:[email protected]> To: <sip:[email protected]> DateTime: 2014-07-10T16:44:56Z NS: imdn <urn:ietf:params:imdn> imdn.Message-ID: 74MgSGNuCflRXJtHR2qWTz7vUlCcqlsG imdn.Disposition-Notification: positive-delivery, display Content-Type: text/plain;charset=utf-8 Content-Length: 8 Xjckvkvk --gc0p4Jq0M2Yt08j34c0p Content-Type: application/sdp v=0 o=- 15522009643326747650 15522009643326773420 IN IP4 media.example.com s=- c=IN IP4 media.example.com t=0 0 m=message 9000 TCP/MSRP * a=accept-types:application/im-iscomposing+xml message/cpim a=accept-wrapped-types:message/imdn+xml text/plain application/vnd.gsma.rcspushlocation+xml application/vnd.gsma.rcs-ft-http+xml a=sendrecv a=path:msrp://media.example.com:9000/UHjL9kLC;tcp a=setup:actpass --gc0p4Jq0M2Yt08j34c0p-- --end msg-- 10-07-2014 16:44:56.943 Debug stack.cpp:410: Queuing cloned received message 0x7ff93035a8c8 for worker threads 10-07-2014 16:44:56.943 Debug stack.cpp:189: Worker thread dequeue message 0x7ff93035a8c8 10-07-2014 16:44:56.943 Debug pjsip: sip_endpoint.c Distributing rdata to modules: Request msg INVITE/cseq=1 (rdata0x7ff93035a8c8) 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:257: Proxy RX request 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:450: Initial (not in-dialog) request for routing proxy 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:501: No Route header, so treat as terminating request 10-07-2014 16:44:56.944 Debug acr.cpp:48: Created ACR (0x7ff93025ab80) 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:593: Trust mode TRUSTED(,,), serving state term (new) 10-07-2014 16:44:56.944 Debug pjsip: tsx0x7ff930003 Transaction created for Request msg INVITE/cseq=1 (rdata0x7ff93035a8c8) 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:2143: UASTransaction constructor (0x7ff9302cd260) 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:2144: ACR (0x7ff93025ab80) 10-07-2014 16:44:56.944 Debug pjsip: tsx0x7ff930003 Incoming Request msg INVITE/cseq=1 (rdata0x7ff93035a8c8) in state Null 10-07-2014 16:44:56.944 Debug pjsip: tsx0x7ff930003 State changed from Null to Trying, event=RX_MSG 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:365: tsx0x7ff930003858 - tu_on_tsx_state UAS, TSX_STATE RX_MSG state=Trying 10-07-2014 16:44:56.944 Debug pjsip: endpoint Response msg 408/INVITE/cseq=1 (tdta0x7ff9300ed0d0) created 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:3578: Report SAS start marker - trail (b764b) 10-07-2014 16:44:56.944 Debug pjsip: tsx0x7ff930003 Sending Response msg 100/INVITE/cseq=1 (tdta0x7ff930354390) in state Trying 10-07-2014 16:44:56.944 Verbose stack.cpp:242: TX 395 bytes Response msg 100/INVITE/cseq=1 (tdta0x7ff930354390) to TCP xxx.xxx.xxx.101:45311: --start msg-- SIP/2.0 100 Trying Via: SIP/2.0/TCP xxx.xxx.xxx.101:5510;received=xxx.xxx.xxx.101;branch=z9hG4bK97cdab82-dbe2-42a6-92c7-4db45587fa2d Call-ID: c1855804-1075-4053-9047-b7c869c24ae0 From: <sip:[email protected]>;tag=18d3e679-45cd-470b-9bd4-ec43e8dfbf78 To: <sip:[email protected];user=phone>;tag=z9hG4bK97cdab82-dbe2-42a6-92c7-4db45587fa2d CSeq: 1 INVITE Content-Length: 0 --end msg-- 10-07-2014 16:44:56.944 Debug pjsip: tsx0x7ff930003 State changed from Trying to Proceeding, event=TX_MSG 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:365: tsx0x7ff930003858 - tu_on_tsx_state UAS, TSX_STATE TX_MSG state=Proceeding 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:2713: Looking for AS chain for incoming transaction request, serving state = term (new) 10-07-2014 16:44:56.944 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected];user=phone to sip:[email protected] 10-07-2014 16:44:56.944 Debug stateful_proxy.cpp:2770: Looking up iFCs for sip:[email protected] for new AS chain 10-07-2014 16:44:56.945 Debug hssconnection.cpp:367: Making Homestead request for /impu/sip%3A%2B155555550001%40example.com/reg-data 10-07-2014 16:44:56.945 Debug httpconnection.cpp:467: Sending HTTP request : http://xxx.xxx.xxx.51:8888/impu/sip%3A%2B155555550001%40example.com/reg-data (try 0) on new connection 10-07-2014 16:44:56.947 Debug httpconnection.cpp:751: Received header http/1.1200ok with value 10-07-2014 16:44:56.947 Debug httpconnection.cpp:751: Received header content-length with value 2293 10-07-2014 16:44:56.947 Debug httpconnection.cpp:751: Received header content-type with value text/plain 10-07-2014 16:44:56.947 Debug httpconnection.cpp:751: Received header with value 10-07-2014 16:44:56.947 Debug httpconnection.cpp:478: Received HTTP response : <ClearwaterRegData> <RegistrationState>REGISTERED</RegistrationState> <IMSSubscription xsi="http://www.w3.org/2001/XMLSchema-instance"; noNamespaceSchemaLocation="CxDataType.xsd"> <PrivateID>[email protected]</PrivateID> <ServiceProfile> <PublicIdentity> <Identity>sip:[email protected]</Identity> </PublicIdentity> <InitialFilterCriteria> <Priority>0</Priority> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>0</Group> <Method>INVITE</Method> </SPT> <SPT> <ConditionNegated>1</ConditionNegated> <Group>0</Group> <SIPHeader> <Header>User-Agent</Header> <Content>CustomEntry</Content> </SIPHeader> </SPT> <SPT> <ConditionNegated>1</ConditionNegated> <Group>0</Group> <SessionDescription> <Line>m</Line> <Content>.*[Rr][Tt][Pp]</Content> </SessionDescription> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>1</Group> <Method>MESSAGE</Method> </SPT> <SPT> <ConditionNegated>1</ConditionNegated> <Group>1</Group> <SIPHeader> <Header>User-Agent</Header> <Content>CustomEntry</Content> </SIPHeader> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:xxx.xxx.xxx.101:5510</ServerName> <DefaultHandling>1</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> <InitialFilterCriteria> <Priority>1</Priority> <TriggerPoint> <ConditionTypeCNF>0</ConditionTypeCNF> <SPT> <ConditionNegated>0</ConditionNegated> <Group>2</Group> <Method>REGISTER</Method> <Extension> <RegistrationType>0</RegistrationType> </Extension> </SPT> <SPT> <ConditionNegated>0</ConditionNegated> <Group>3</Group> <Method>REGISTER</Method> <Extension> <RegistrationType>1</RegistrationType> </Extension> </SPT> </TriggerPoint> <ApplicationServer> <ServerName>sip:xxx.xxx.xxx.101:5510</ServerName> <DefaultHandling>1</DefaultHandling> </ApplicationServer> </InitialFilterCriteria> </ServiceProfile> </IMSSubscription> </ClearwaterRegData> 10-07-2014 16:44:56.947 Debug hssconnection.cpp:293: Processing Identity node from HSS XML - sip:[email protected] 10-07-2014 16:44:56.947 Debug stateful_proxy.cpp:2774: Successfully looked up iFCs 10-07-2014 16:44:56.947 Debug aschain.cpp:74: Creating AsChain 0x7ff930155890 with 2 IFC and adding to map 10-07-2014 16:44:56.947 Debug aschain.cpp:76: Attached ACR (0x7ff93025ab80) to chain 10-07-2014 16:44:56.947 Debug stateful_proxy.cpp:4954: UASTransaction 0x7ff9302cd260 linked to AsChain AsChain-term[0x7ff930155890]:1/2 10-07-2014 16:44:56.947 Debug stateful_proxy.cpp:2654: Terminating half 10-07-2014 16:44:56.947 Debug stateful_proxy.cpp:2926: Apply terminating services 10-07-2014 16:44:56.948 Debug ifchandler.cpp:476: SPT class Method: result true 10-07-2014 16:44:56.948 Debug ifchandler.cpp:583: Add to group 0 val true 10-07-2014 16:44:56.948 Debug ifchandler.cpp:476: SPT class SIPHeader: result true 10-07-2014 16:44:56.948 Debug ifchandler.cpp:583: Add to group 0 val false 10-07-2014 16:44:56.948 Debug ifchandler.cpp:476: SPT class SessionDescription: result false 10-07-2014 16:44:56.948 Debug ifchandler.cpp:583: Add to group 0 val true 10-07-2014 16:44:56.949 Debug ifchandler.cpp:476: SPT class Method: result false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:583: Add to group 1 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:476: SPT class SIPHeader: result true 10-07-2014 16:44:56.949 Debug ifchandler.cpp:583: Add to group 1 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:601: Result group 0 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:601: Result group 1 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:605: iFC does not match 10-07-2014 16:44:56.949 Debug aschain.cpp:217: No match for AsChain-term[0x7ff930155890]:1/2 10-07-2014 16:44:56.949 Debug stateful_proxy.cpp:2981: Done internal step - advance link to AsChain-term[0x7ff930155890]:2/2 and go around again 10-07-2014 16:44:56.949 Debug ifchandler.cpp:476: SPT class Method: result false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:583: Add to group 2 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:476: SPT class Method: result false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:583: Add to group 3 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:601: Result group 2 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:601: Result group 3 val false 10-07-2014 16:44:56.949 Debug ifchandler.cpp:605: iFC does not match 10-07-2014 16:44:56.949 Debug aschain.cpp:217: No match for AsChain-term[0x7ff930155890]:2/2 10-07-2014 16:44:56.949 Debug stateful_proxy.cpp:2981: Done internal step - advance link to AsChain-term[0x7ff930155890]:3/2 and go around again 10-07-2014 16:44:56.949 Debug aschain.cpp:206: No ASs left in chain 10-07-2014 16:44:56.949 Info stateful_proxy.cpp:2929: Terminating services disposition 2 10-07-2014 16:44:56.949 Debug stateful_proxy.cpp:2663: Single Record-Route - end of terminating handling 10-07-2014 16:44:56.949 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected];user=phone to sip:[email protected] 10-07-2014 16:44:56.949 Info stateful_proxy.cpp:1869: Look up targets in registration store: sip:[email protected] 10-07-2014 16:44:56.949 Debug regstore.cpp:102: Get AoR data for sip:[email protected] 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:260: Key reg\\sip:[email protected] hashes to vbucket 88 via hash 0xf1e7f0d8 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:304: 1 read replicas for key reg\\sip:[email protected] 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:337: Attempt to read from replica 0 (connection 0x7ff9302d2950) 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:343: Fetch result 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:351: Found record on replica 0 10-07-2014 16:44:56.949 Debug memcachedstore.cpp:400: Read 651 bytes from table reg key sip:[email protected], CAS = 104680 10-07-2014 16:44:56.949 Debug regstore.cpp:455: Deserialize 1 bindings 10-07-2014 16:44:56.949 Debug regstore.cpp:462: Binding <urn:gsma:imei:35912505-094305-1>:1 10-07-2014 16:44:56.949 Debug regstore.cpp:488: Deserialize 1 path headers 10-07-2014 16:44:56.949 Debug regstore.cpp:494: Deserialized path header <sip:xxx.xxx.xxx.40:5060;lr> 10-07-2014 16:44:56.949 Debug regstore.cpp:503: Deserialize 0 subscriptions 10-07-2014 16:44:56.949 Debug regstore.cpp:114: Data store returned a record, CAS = 104680 10-07-2014 16:44:56.949 Debug stateful_proxy.cpp:1926: Target = <sip:[email protected]:46670;transport=TCP;ob> 10-07-2014 16:44:56.949 Debug stateful_proxy.cpp:3677: Allocating transaction and data for target 0 10-07-2014 16:44:56.950 Debug pjsip: tsx0x7ff9300df Transaction created for Request msg INVITE/cseq=1 (tdta0x7ff930358290) 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:3697: Adding trail identifier 751179 to UAC transaction 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:3716: Updating request URI and route for target 0 10-07-2014 16:44:56.950 Debug pjutils.cpp:219: aor_from_uri converted sip:[email protected];user=phone to sip:[email protected] 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:4112: Adding a Route header to sip:xxx.xxx.xxx.40:5060;transport= 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:4122: Target came from store, storing AoR = sip:[email protected], binding_id = <urn:gsma:imei:35912505-094305-1>:1 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:4150: Resolve next hop destination 10-07-2014 16:44:56.950 Debug pjutils.cpp:463: Next hop node is encoded in top route header 10-07-2014 16:44:56.950 Debug sipresolver.cpp:85: SIPResolver::resolve for name xxx.xxx.xxx.40, port 5060, transport -1, family 2 10-07-2014 16:44:56.950 Debug baseresolver.cpp:480: Attempt to parse xxx.xxx.xxx.40 as IP address 10-07-2014 16:44:56.950 Debug sipresolver.cpp:102: Target is an IP address - default port/transport if required 10-07-2014 16:44:56.950 Info pjutils.cpp:734: Resolved destination URI sip:xxx.xxx.xxx.40:5060;lr to 1 servers 10-07-2014 16:44:56.950 Debug stateful_proxy.cpp:4188: Sending request for sip:[email protected]:46670;transport=TCP;ob 10-07-2014 16:44:56.950 Debug pjsip: tsx0x7ff9300df Sending Request msg INVITE/cseq=1 (tdta0x7ff930358290) in state Null 10-07-2014 16:44:56.950 Debug pjsip: endpoint Request msg INVITE/cseq=1 (tdta0x7ff930358290): skipping target resolution because address is already set 10-07-2014 16:44:56.950 Verbose stack.cpp:242: TX 1268 bytes Request msg INVITE/cseq=1 (tdta0x7ff930358290) to UDP xxx.xxx.xxx.40:5060: --start msg-- INVITE sip:[email protected]:46670;transport=TCP;ob SIP/2.0 Record-Route: <sip:sprout01.example.com:5054;transport=TCP;lr;charge-term> Via: SIP/2.0/UDP xxx.xxx.xxx.41:5054;rport;branch=z9hG4bKPjPGEgPYOdx8sxqUOtzHyhPqE2fRbIoV3i Via: SIP/2.0/TCP xxx.xxx.xxx.101:5510;received=xxx.xxx.xxx.101;branch=z9hG4bK97cdab82-dbe2-42a6-92c7-4db45587fa2d From: <sip:[email protected]>;tag=18d3e679-45cd-470b-9bd4-ec43e8dfbf78 To: <sip:[email protected];user=phone> Call-ID: c1855804-1075-4053-9047-b7c869c24ae0 CSeq: 1 INVITE Contact: <sip:[email protected]:5510>;+g.oma.sip-im;+sip.instance="<urn:gsma:imei:35513605-331763-5>" Accept-Contact: *;+g.oma.sip-im Allow: INVITE, ACK, CANCEL, BYE, UPDATE, REFER, SUBSCRIBE, MESSAGE, REGISTER, INFO User-Agent: IM-serv/OMA1.0 CustomEntry-RMS/2.0 Supported: timer, gruu Session-Expires: 600;refresher=uas Min-SE: 400 P-Asserted-Identity: <sip:[email protected]> Subject: Xjckvkvk Contribution-ID: WtNdhjExDY8aqwiQ8ffTo0k4rsnlnI1LsLZD P-Charging-Vector: icid-value="30fdc0efc89051a5a2de485d92166e5a";orig-ioi=example.com;term-ioi=example.com Max-Forwards: 69 P-Called-Party-ID: <sip:[email protected]> Route: <sip:xxx.xxx.xxx.40:5060;lr> Content-Length: 0 --end msg-- _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater _______________________________________________ Clearwater mailing list [email protected] http://lists.projectclearwater.org/listinfo/clearwater
