[cisco-voip] SIP 400 Bad request

Mon Mar 15 21:59:51 EDT 2010

Just an update on this, call works fine now.
SBC had removed the P-asserted-identity.

Thanks for all your help!

On Thu, Mar 11, 2010 at 12:26 PM, Jefflin Choi <jefflin.choi at gmail.com> wrote:
> Thanks a lot for the suggestion. I'll ask the provider to put bracket
> and see if calls goes thru.
>
> regards,
> jeff
>
> On Wed, Mar 10, 2010 at 1:07 PM, Nick Matthews <matthnick at gmail.com> wrote:
>> RFC 3261 would seem to agree for the From, Contact, and To headers:
>>
>>   The Contact, From, and To header fields contain a URI.  If the URI
>>   contains a comma, question mark or semicolon, the URI MUST be
>>   enclosed in angle brackets (< and >).  Any URI parameters are
>>   contained within these brackets.  If the URI is not enclosed in angle
>>   brackets, any semicolon-delimited parameters are header-parameters,
>>   not URI parameters.
>>
>> But, RFC 3325 (P-asserted-identity) states that the formal syntax
>> follows RFC 2234 (I know, FUN):
>>
>> The names <rulename>, <Rulename>, <RULENAME> and <rUlENamE> all refer
>>   to the same rule.   Unlike original BNF, angle brackets ("<", ">")
>> are not  required.
>>   However, angle brackets may be used around a rule name whenever their
>>   presence will facilitate discerning the use of  a rule name.  This is
>>   typically restricted to rule name references in free-form prose, or
>>   to distinguish partial rules that combine into a string not separated
>>   by white space, such as shown in the discussion about repetition,
>>   below.
>>
>>
>> In short - see if your provider can put angle brackets on the paID.
>> It's kind of a grey area for this particular header because you're
>> bringing in a separate paID RFC for the enforcement.
>>
>> -nick
>>
>>
>>
>> On Tue, Mar 9, 2010 at 11:11 PM, Kevin Thorngren <kthorngr at cisco.com> wrote:
>>> It looks like CUCM does not like the P-Asserted-identity header:
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/checkSyntaxAndSelectAssertedHeader: PAI
>>> result [16], total[0], sipUri[0], sipsUri[0],
>>> telUri[0]|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo:
>>> parseResult[16]|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/Stack/Info/0xeb1e468/ccsip_api_call_setup_ind returned:
>>> SIP_MSG_PARSE_ERR|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> The header in the Invite looks like this:
>>> P-Asserted-Identity: sip:28303941 at 10.249.0.6;user=phone
>>> Don't know for sure but I think it should look like this with <> surrounding
>>> URI
>>> P-Asserted-Identity: <sip:28303941 at 10.249.0.6;user=phone>
>>> Kevin
>>> On Mar 9, 2010, at 9:42 PM, Jefflin Choi wrote:
>>>
>>> Hi all,
>>>
>>> Thanks a lot for all the suggestions.
>>> I am asking the provider now to double check their configs.
>>>
>>> Attached are the detailed sdi and sdl traces.
>>> unfortunately, my reading experience with CCM trace is not so good.
>>> 10.249.224.18 is the SBC's ip add. 8806301 is the cisco ip phone's number
>>> being called. CCM's IP is 10.10.6.9.
>>>
>>> ------------------
>>> Date: Wed, 03 Mar 2010 02:17:24 GMT
>>> Allow: INVITE, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE,
>>> NOTIFY
>>> From: "hbuser"<sip:hbuser at 10.249.0.6:5061>;tag=ucAC100849
>>> Content-Length: 0
>>> To: <sip:10.249.190.2:5060>;tag=1033457050
>>> Call-ID: 1A840A0000 at 10.249.0.6
>>> Via: SIP/2.0/UDP 10.249.224.18:5060;branch=z9hG4bKlihiah10bo80pa08s2k1.1
>>> CSeq: 1 OPTIONS
>>>
>>> |<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.23><IP::10.249.224.18><DEV::><LVL::State
>>> Transition><MASK::20000>
>>> 03/03/2010 10:17:24.447 CCM|EnvProcessUdpPort -
>>> EnvProcessUdpHandler::fireSignal() varId =
>>> 0|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.23><IP::10.249.224.18><DEV::><LVL::Arbitrary><MASK::0800>
>>> 03/03/2010 10:17:24.447 CCM|EnvProcessUdpPort -
>>> EnvProcessUdpHandler::send(buff, 380,
>>> 10.249.224.18:5060)|<CLID::StandAloneCluster><NID::10.10.6.9><LVL::Arbitrary><MASK::0800>
>>> 03/03/2010 10:17:26.205 CCM|EnvProcessUdpHandler::handle_input   Status: 0,
>>> Id: 0|<CLID::StandAloneCluster><NID::10.10.6.9><LVL::Arbitrary><MASK::0800>
>>> 03/03/2010 10:17:26.205 CCM|//SIP/SIPUdp/wait_UdpDataInd: Incoming SIP UDP
>>> message size 1035 from 10.249.224.18:[5060]:
>>> INVITE sip:8806301 at 10.10.6.9:5060;user=phone SIP/2.0
>>> Via: SIP/2.0/UDP 10.249.224.18:5060;branch=z9hG4bKl2olcr10e0khva0832o1.1
>>> From: "28303941"<sip:28303941 at 10.249.0.14:5061;user=phone>;tag=uc192E625E
>>> To: <sip:028806301 at 10.249.0.6:5061;user=phone>
>>> P-Asserted-Identity: sip:28303941 at 10.249.0.6;user=phone
>>> Supported: 100rel,timer
>>> Content-Type: application/sdp
>>> Session-Expires: 1800
>>> Call-ID: 1B840C0000 at 10.249.0.6
>>> CSeq: 1 INVITE
>>> Allow:
>>> INVITE,ACK,OPTIONS,BYE,CANCEL,UPDATE,REGISTER,INFO,PRACK,SUBSCRIBE,NOTIFY,MESSAGE
>>> Contact: <sip:28303941 at 10.249.224.18:5060;transport=udp>
>>> Max-Forwards: 69
>>> Content-Length: 411
>>>
>>> v=0
>>> o=UTSTARCOM 0 0 IN IP4 10.249.224.18
>>> s=-
>>> c=IN IP4 10.249.224.18
>>> t=0 0
>>> m=audio 65190 RTP/AVP 8 127 18 0 4 102 15
>>> a=sendrecv
>>> a=fmtp:8 X-ptime: 20
>>> a=fmtp:127 X-ptime: 20
>>> a=fmtp:18 X-ptime: 20 30 40 10
>>> a=fmtp:0 X-ptime: 20 15 10 5
>>> a=fmtp:4 X-ptime: 30 60 90 120
>>> a=fmtp:102 X-ptime: 15 10 5 0
>>> a=fmtp:15 X-ptime: 20 15 10 5
>>> a=rtpmap:127 telephone-event/8000
>>> a=fmtp:127 0-15
>>> a=rtpmap:102 vbd/8000
>>> |<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::State
>>> Transition><MASK::20000>
>>> 03/03/2010 10:17:26.205 CCM|//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type
>>> returned: 2 for event
>>> 1|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.205
>>> CCM|//SIP/Stack/Transport/0x0/context=(nil)|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.205 CCM|//SIP/Stack/Info/0x0/Checking Invite
>>> Dialog|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0x0/Added context(0xeb1e468)
>>> with key=[22] to
>>> table|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Transport/0x0/Dialog Transaction
>>> Address 10.249.224.18,Port 5060, Transport 1, SentBy Port
>>> 5060|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/States/0xeb1e468/0xeb1e468 : State
>>> change from (STATE_NONE, SUBSTATE_NONE)  to (STATE_IDLE,
>>> SUBSTATE_NONE)|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::State
>>> Transition><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Transport/0x0/Dialog Transaction
>>> Address 10.249.224.18,Port 5060, Transport 1, SentBy Port
>>> 5060|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Transport/0x0/Dialog Transaction
>>> Address 10.249.224.18,Port 5060, Transport 1, SentBy Port
>>> 5060|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0x0/No GTD found in inbound
>>> container|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/****Adding to UAS
>>> Request
>>> table.|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Added to table.
>>> ccb=0xeb1e468
>>> key=1B840C0000 at 10.249.0.68806301|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Calling name
>>> 28303941, number 28303941, Calling oct3 0x00, oct_3a 0x80, ext_priv 0x00,
>>> Called number 8806301,
>>> o|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Carrier id code ,
>>> prev_cid NONE, next_cid NONE, prev_tgrp NONE, next_tgrp
>>> NONE|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/sipSPIGetCallExtensionSupported:
>>> SIPRel1xxEnabledServiceParamSetting=1 ,
>>> ccb->pld.outboundRel1xx=1|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Requires
>>> reliable-provisional
>>> support|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/SIPHandler/ccbId=0/scbId=0/sip_stop_timer:
>>> type=SIP_TIMER_EXPIRES value=1800000
>>> retries=0|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/sip_start_timer: type=SIP_TIMER_EXPIRES
>>> value=1800000
>>> retries=0|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/checkSyntaxAndSelectAssertedHeader: PAI
>>> result [16], total[0], sipUri[0], sipsUri[0],
>>> telUri[0]|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo:
>>> parseResult[16]|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::20000>
>>> 03/03/2010 10:17:26.206
>>> CCM|//SIP/Stack/Info/0xeb1e468/ccsip_api_call_setup_ind returned:
>>> SIP_MSG_PARSE_ERR|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/****Adding to UAS
>>> Response
>>> table.|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Added to table.
>>> ccb=0xeb1e468
>>> key=1B840C0000 at 10.249.0.61534499114|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0xeb1e468/msg=0xdd435a8,
>>> addr=10.249.224.18, port=5060, sentBy_port=5060, is_req=0, transport=1,
>>> switch=0,
>>> callBack=0x9cbab98|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0xeb1e468/Proceedable for
>>> sending msg
>>> immediately|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0xeb1e468/switch transport
>>> is
>>> 0|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0x0/Posting send for
>>> msg=0xdd435a8, addr=10.249.224.18, port=5060, connId=0 for
>>> UDP|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/Stack/Info/0xeb1e468/Sent an 3456XX Error
>>> Response|<CLID::StandAloneCluster><NID::10.10.6.9><CT::1,100,186,1.24><IP::10.249.224.18><DEV::><LVL::Detailed><MASK::40000>
>>> 03/03/2010 10:17:26.207 CCM|//SIP/SIPUdp/wait_SdlSPISignal: Outgoing SIP UDP
>>> message to 10.249.224.18:[5060]:
>>> SIP/2.0 400 Bad Request
>>> Date: Wed, 03 Mar 2010 02:17:26 GMT
>>> From: "28303941"<sip:28303941 at 10.249.0.14:5061;user=phone>;tag=uc192E625E
>>> Allow-Events: presence
>>> Content-Length: 0
>>> To: <sip:028806301 at 10.249.0.6:5061;user=phone>;tag=1534499114
>>> Call-ID: 1B840C0000 at 10.249.0.6
>>> Via: SIP/2.0/UDP 10.249.224.18:5060;branch=z9hG4bKl2olcr10e0khva0832o1.1
>>> CSeq: 1 INVITE
>>> ---------------------------
>>> Hope we can get some info out of it.
>>>
>>> @ Mark,
>>> i'm having provide check on it.
>>>
>>> I tried a cube but a different error came up.
>>> 403 or 500 something. Maybe something's wrong on my cube configuration. Will
>>> reconfigure the cube again and try it out.
>>>
>>> Thanks,
>>> Jeff
>>>
>>>
>>>
>>>
>>> On Wed, Mar 10, 2010 at 12:08 AM, Mark Holloway <mh at markholloway.com> wrote:
>>>>
>>>> Two things catch my attention.
>>>>
>>>> 1) The Request URI and the To header are different.  The To header is
>>>> prepended with two extra digits and the host port is 5061.  The Request URI
>>>> does not contain the digits 02 and the host port is 5060 as opposed to 5061.
>>>>
>>>> 2) The format of the SDP looks odd.  I'm not suggesting it's wrong, but
>>>> that is not how I typically see the SDP formatted.  I recently experienced
>>>> an issue where an IAD was rejecting media establishment due to an
>>>> unsupported SDP parameter being sent by a Toshiba CIX using a SIP Trunk.  It
>>>> is possible that UCM does not like something in the SDP.
>>>>
>>>> Is the SBC managed by you or your provider?  Do you have the ability to
>>>> test your CCM SIP Trunk with CUBE?
>>>>
>>>> If I were you I would focus on the Request URI vs. To header first and see
>>>> if that clear up your problem.
>>>>
>>>> On Mar 9, 2010, at 5:55 AM, Jefflin Choi wrote:
>>>>
>>>> > Hi,
>>>> >
>>>> > I'm trying to troubleshoot and incoming call from SBC to CCM SIP trunk.
>>>> > Outgoing call to SBC from IP Phone works fine. using G711ulaw codec without
>>>> > security.
>>>> >
>>>> > Topology:
>>>> > SIP server ------------SBC(SIP)---------CCM7-----IP Phone(SCCP)
>>>> >
>>>> > Problem
>>>> > I'm getting 400 Bad request from Sniffer trace. I checked my Partition
>>>> > and CSS including transformation mask and saw no problem.
>>>> > We are using UDP for sip protocol.
>>>> >
>>>> > Q.
>>>> > Any idea why CCM7 is sending 400 Bad request? There seem to be a reason
>>>> > CCM7 is rejecting the SIP invite however i could not find it.
>>>> >
>>>> > Attached is the captured sniffer trace on CCM.
>>>> >
>>>> > Thanks in advance for the help.
>>>> >
>>>> > regards,
>>>> > Jeff
>>>> >
>>>> >
>>>> >
>>>> >
>>>> >
>>>> >
>>>> > <sip invite 400 bad
>>>> > request.pcap>_______________________________________________
>>>> > cisco-voip mailing list
>>>> > cisco-voip at puck.nether.net
>>>> > https://puck.nether.net/mailman/listinfo/cisco-voip
>>>>
>>>
>>> <pldtdemo_CiscoCallManager_sdi_2010-03-10_10-21-35.zip><pldtdemo_CiscoCallManager_sdl_2010-03-10_10-21-35.zip>_______________________________________________
>>> cisco-voip mailing list
>>> cisco-voip at puck.nether.net
>>> https://puck.nether.net/mailman/listinfo/cisco-voip
>>>
>>>
>>> _______________________________________________
>>> cisco-voip mailing list
>>> cisco-voip at puck.nether.net
>>> https://puck.nether.net/mailman/listinfo/cisco-voip
>>>
>>>
>>
>