getting 400 Bad request on CCM7 SIP trunk

jechoi · ‎03-09-2010

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 and SIP trunk config screen captures.

Thanks in advance for the help.

regards,
Jeff

Aaron Harrison · ‎03-09-2010

Hi

You'll need to check your CCM traces - the packet capture doesn't show what the CCM is doing between receiving the INVITE and sending the 400 back...

Regards

Aaron

Aaron Please remember to rate helpful posts to identify useful responses, and mark 'Answered' if appropriate!

jechoi · ‎03-09-2010

Hi Aaron,

Just finished troubleshooting trace collection problem on the CCM.Anyway, attached it the SDI/SDL trace from the CCM.

----------from sdi trace----

SIP/2.0 200 OK
Date: Wed, 03 Mar 2010 02:17:24 GMT
Allow: INVITE, INFO, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY
From: "hbuser";tag=ucAC100849
Content-Length: 0
To: <10.249.190.2:5060>;tag=1033457050
Call-ID: 1A840A0000@10.249.0.6
Via: SIP/2.0/UDP 10.249.224.18:5060;branch=z9hG4bKlihiah10bo80pa08s2k1.1
CSeq: 1 OPTIONS

|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:STATE transition=""><:20000>
03/03/2010 10:17:24.447 CCM|EnvProcessUdpPort - EnvProcessUdpHandler::fireSignal() varId = 0|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:ARBITRARY><:0800>
03/03/2010 10:17:24.447 CCM|EnvProcessUdpPort - EnvProcessUdpHandler::send(buff, 380, 10.249.224.18:5060)|<:STANDALONECLUSTER><:10.10.6.9><:ARBITRARY><:0800>
03/03/2010 10:17:26.205 CCM|EnvProcessUdpHandler::handle_input Status: 0, Id: 0|<:STANDALONECLUSTER><:10.10.6.9><:ARBITRARY><: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@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"<28303941>;tag=uc192E625E
To: <028806301>
P-Asserted-Identity: sip:28303941@10.249.0.6;user=phone
Supported: 100rel,timer
Content-Type: application/sdp
Session-Expires: 1800
Call-ID: 1B840C0000@10.249.0.6
CSeq: 1 INVITE
Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,UPDATE,REGISTER,INFO,PRACK,SUBSCRIBE,NOTIFY,MESSAGE
Contact: <28303941>
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
|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:STATE transition=""><:20000>
03/03/2010 10:17:26.205 CCM|//SIP/Stack/Info/0x0/ccsip_spi_get_msg_type returned: 2 for event 1|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.205 CCM|//SIP/Stack/Transport/0x0/context=(nil)|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.205 CCM|//SIP/Stack/Info/0x0/Checking Invite Dialog|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0x0/Added context(0xeb1e468) with key=[22] to table|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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)|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:STATE transition=""><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0x0/No GTD found in inbound container|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/****Adding to UAS Request table.|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Added to table. ccb=0xeb1e468 key=1B840C0000@10.249.0.68806301|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/SIPHandler/ccbId=0/scbId=0/sipSPIGetCallExtensionSupported: SIPRel1xxEnabledServiceParamSetting=1 , ccb->pld.outboundRel1xx=1|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:20000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Requires reliable-provisional support|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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]|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:20000>
03/03/2010 10:17:26.206 CCM|//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo: parseResult[16]|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:20000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/ccsip_api_call_setup_ind returned: SIP_MSG_PARSE_ERR|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/****Adding to UAS Response table.|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.206 CCM|//SIP/Stack/Info/0xeb1e468/Added to table. ccb=0xeb1e468 key=1B840C0000@10.249.0.61534499114|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0xeb1e468/Proceedable for sending msg immediately|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.207 CCM|//SIP/Stack/Transport/0xeb1e468/switch transport is 0|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:40000>
03/03/2010 10:17:26.207 CCM|//SIP/Stack/Info/0xeb1e468/Sent an 3456XX Error Response|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><: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"<28303941>;tag=uc192E625E
Allow-Events: presence
Content-Length: 0
To: <028806301>;tag=1534499114
Call-ID: 1B840C0000@10.249.0.6
Via: SIP/2.0/UDP 10.249.224.18:5060;branch=z9hG4bKl2olcr10e0khva0832o1.1
CSeq: 1 INVITE

----------------------------------

8806301 is the ip phone being called. Provider should send 028806301 to CCM as callerid. 10.10.6.9 the the ip address of the CCM. 10.249.224.18 is the SBC's ip address.

Unfortunately, my reading skills on the traces are not so good. hope we can get a clue on this trace.

thanks,

Jeff

abenhida · ‎03-29-2010

Hi Jeff,

Did u find the answer to this yet?

If not, what I understand from this is that there is something that may not be liked in that invite - I see there is a presence of GTD - (GTD found in inbound container), it could be that.

Ahmed

jechoi · ‎03-29-2010

Hi Ahmed,

Yes. Got help from other site.

CCM is rejecting the P-ASserted Identifier.

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]|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:20000>
03/03/2010 10:17:26.206 CCM|//SIP/SIPHandler/ccbId=0/scbId=0/extractAssertedInfo: parseResult[16]|<:STANDALONECLUSTER><:10.10.6.9><:1><:10.249.224.18><:><:DETAILED><:20000>

Softswitch is sending:

From: "28303941"<28303941>;tag=uc192E625E
To: <028806301>
P-Asserted-Identity: sip:28303941@10.249.0.6;user=phone <<----

The correct syntax CCM is expecting is with <> bracket as i was told.

SBC made the modification by removing the P-Asserted-Identity field since CCM can't do it. Worked ok now.

Got some other problems appeared after that but i eventually learned a bit to read ccm logs in the process thanks to this so it worked out fine.

Thanks for the followup.

cheers,

Jeff