Solved: Wrong ACK packet . AS5300 gw doesn't send branch on VIA header of INVITE sip packet

nawfeloujdi · ‎01-17-2011

Hello everyone!!

I m facing a strange behaviour with my AS5300 voice gateway. When the gw is connected directly to PBX everythings works well but when i put a sip proxy forwarding calls between gw and PBX all the calls hangs up after 5 sec (+or -). Looking into the trace sip i realize that gw send a wrong ACK in reply of INVITE , then sip proxy discard it and PBX hangs the call cause he never receive the ACK.

ACK sip:79.125.120.12:5060;lr=on;did=ce.3716ea02 SIP/2.0

Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"

From: <sip:911873699@cisco_gw>;tag=65FB8-B18

Route: <sip:911111500@PBX:5060>

To: <sip:911111500@sip_proxy>;tag=as7f388e3f

Date: Mon, 17 Jan 2011 09:26:36 GMT

Call-ID: B6F61A2E-215211E0-802BD462-C4432B89@cisco_gw

To work fine , the content of Route header should be in ACK header and viceversa.

I tried to compare between the sip trace of a wrong call and a good one (using other cisco gw AS5350 who works well with sip proxy in the same escenario) and i realize that the only difference is the INVITE of wrong case doesn' t send branch number in the via header.

INVITE sip:911111500@sip_proxy:5060 SIP/2.0

Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"

From: <sip:911873699@cisco_gw>;tag=65FB8-B18

To: <sip:911111500@sip_proxy>

i m using c5300-is-mz.123-26.bin ios version.

Anybody understand what is happening in there?? is there any solution?? i ll send more information if it s requested.

Thanks in advance.

Nawfel Oujdi

Daniele Giordano · ‎01-19-2011

Can you also post the output of "debug ccapi inout" of a problematic call?

Thanks.

View solution in original post

Daniele Giordano · ‎01-18-2011

Can you post the configuration of your AS and the full output of "debug ccsip messages"?

Regards.

nawfeloujdi · ‎01-19-2011

hello Daniele!

As you requested (Hop that will be helpfull):

1- Config:

Current configuration : 6359 bytes
!
version 12.3
service timestamps debug datetime msec
service timestamps log datetime msec
service password-encryption
!
hostname paxson
!
boot-start-marker
boot system flash c5300-is-mz.123-26.bin
boot-end-marker
!
enable secret 5
!
!
!
resource-pool disable
clock timezone CET 1
clock summer-time CEST recurring last Sun Mar 2:00 last Sun Oct 3:00
!
calltracker enable
calltracker history max-size 30
calltracker call-record verbose
no aaa new-model
ip subnet-zero
no ip source-route
ip cef
ip name-server 8.8.8.8
ip name-server 8.8.4.4
!
!
trunk group Orange911111500
carrier-id Orange
hunt-scheme longest-idle
!
isdn switch-type primary-net5
!
voice call carrier capacity active
!
!
controller E1 0
framing NO-CRC4
clock source line primary
pri-group timeslots 1-31

controller E1 1
framing NO-CRC4
clock source line secondary 1
pri-group timeslots 1-31
!
controller E1 2
framing NO-CRC4
clock source line secondary 2
pri-group timeslots 1-31
!
controller E1 3
framing NO-CRC4
clock source line secondary 3
pri-group timeslots 1-31
!
!
interface Ethernet0
no ip address
shutdown
!
interface Serial0
no ip address
shutdown
clock rate 2015232
no fair-queue
!
interface Serial1
no ip address
shutdown
clock rate 2015232
no fair-queue
!
interface Serial2
no ip address
shutdown
clock rate 2015232
no fair-queue
!
interface Serial3
no ip address
shutdown
clock rate 2015232
no fair-queue
!
interface Serial0:15
no ip address
encapsulation hdlc
trunk-group Orange911111500
isdn switch-type primary-net5
isdn incoming-voice modem
isdn map address .* plan unknown type unknown
no cdp enable
!
interface Serial1:15
no ip address
encapsulation hdlc
trunk-group Orange911111500
isdn switch-type primary-net5
isdn incoming-voice modem
isdn map address .* plan unknown type unknown
no cdp enable
!
interface Serial2:15
no ip address
encapsulation hdlc
trunk-group Orange911111500
isdn switch-type primary-net5
isdn incoming-voice modem
isdn map address .* plan unknown type unknown
no cdp enable
!
interface Serial3:15
no ip address
encapsulation hdlc
trunk-group Orange911111500
isdn switch-type primary-net5
isdn incoming-voice modem
isdn map address .* plan unknown type unknown
no cdp enable
!
interface FastEthernet0
ip address 80.68.138.225 255.255.255.240
duplex auto
speed auto
!
ip classless
ip route 0.0.0.0 0.0.0.0 80.68.138.235
no ip http server
!
!
voice-port 0:D
cptone ES
!
voice-port 1:D
cptone ES
!
voice-port 2:D
cptone ES
!
voice-port 3:D
cptone ES
!
!
dial-peer cor custom
!
!
!
dial-peer voice 101 pots
trunkgroup Orange911111500
description POTS DEFAULT
huntstop
incoming called-number .
direct-inward-dial
!
dial-peer voice 501 voip
description VoIP Cisco->IVR's Produccion
preference 1
destination-pattern ^.........$
session protocol sipv2
session target dns:sip_server
dtmf-relay rtp-nte
no vad
!
!
gateway
!
!
line con 0
line aux 0
line vty 0 4
!
ntp clock-period 17179875
ntp update-calendar
ntp server 130.206.3.166
end

2- "debug ccsip messages"

INVITE sip:911111500@sip_server:5060 SIP/2.0
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
From: ;tag=A487C6C-1789
To: <911111500>
Date: Wed, 19 Jan 2011 09:14:59 GMT
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
Supported: timer,100rel
Min-SE: 1800
Cisco-Guid: 1820356101-585306592-3091453026-3292736393
User-Agent: Cisco-SIPGateway/IOS-12.x
Allow: INVITE, OPTIONS, BYE, CANCEL
, ACK, PRACK, COMET, REFER, SUBSCRIBE, NOTIFY, INFO
CSeq: 101 INVITE
Max-Forwards: 6
Remote-Party-ID: ;party=calling;screen=yes;privacy=off
Timestamp: 1295428499
Contact:
Expires: 180
Allow-Events: telephone-event
Content-Type: application/sdp
Content-Length: 270

v=0
o=CiscoSystemsSIP-GW-UserAgent 8098 2890 IN IP4 cisco_gw
s=SIP Call
c=IN IP4 cisco_gw
t=0 0
m=audio 16858 RTP/AVP 18 101
c=IN IP4 cisco_gw
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

*Jan 19 09:14:59.979: Received:
SIP/2.0 100 Giving a try
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
From: ;tag=A487C6C-1789
To: <911111500>
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
CSeq: 101 INVITE
Server: SIP Sever (1.6.3-notls (i386/linux))
Content-Length: 0

*Jan 19 09:14:59.999: Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
Record-Route:
From: ;tag=A487C6C-1789
To: <911111500>;tag=as0a7043c0
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
CSeq: 101 INVITE
Server: Asterisk PBX 1.6.2.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Require: timer
Session-Expires:
1800;refresher=uas
Contact: <911111500>
Content-Type: application/sdp
Content-Length: 320

v=0
o=root 1141920875 1141920875 IN IP4 asterisk_public_ip
s=Asterisk PBX 1.6.2.13
c=IN IP4 asterisk_public_ip
t=0 0
m=audio 10542 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=oldmediaip:asterisk_local_ip
a=oldmediaip:asterisk_local_ip

*Jan 19 09:15:00.007: Sent:
ACK sip:sip_server:5060;lr=on;did=a71.8f1dc0d1 SIP/2.0
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
From: ;tag=A487C6C-1789
To: <911111500>;tag=as0a7043c0
Date: Wed, 19 Jan 2011 09:14:59 GMT
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
Route: <911111500>
Max-Forwards: 6
Content-Length: 0
CSeq: 101 ACK

*Jan 19 09:15:00.259: Received:
SIP/2.0 200 OK
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
Record-Route:
From: ;tag=A487C6C-1789
To: <911111500>;tag=as0a7043c0
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
CSeq: 101 INVITE
Server: Asterisk PBX 1.6.2.13
Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO
Supported: replaces, timer
Require: timer
Session-Expires:
1800;refresher=uas
Contact: <911111500>
Content-Type: application/sdp
Content-Length: 320

v=0
o=root 1141920875 1141920875 IN IP4 asterisk_public_ip
s=Asterisk PBX 1.6.2.13
c=IN IP4 asterisk_public_ip
t=0 0
m=audio 10542 RTP/AVP 18 101
a=rtpmap:18 G729/8000
a=fmtp:18 annexb=no
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv
a=oldmediaip:asterisk_local_ip
a=oldmediaip:asterisk_local_ip

*Jan 19 09:15:00.267: Sent:
ACK sip:sip_server:5060;lr=on;did=a71.8f1dc0d1 SIP/2.0
Via: SIP/2.0/UDP cisco_gw:5060;x-route-tag="cid:Orange@cisco_gw"
From: ;tag=A487C6C-1789
To: <911111500>;tag=as0a7043c0
Date: Wed, 19 Jan 2011 09:14:59 GMT
Call-ID: 6CB93049-22E311E0-B846D462-C4432B89@cisco_gw
Route: <911111500>
Max-Forwards: 6
Content-Length: 0
CSeq: 101 ACK

Best regards

Daniele Giordano · ‎01-19-2011

Can you also post the output of "debug ccapi inout" of a problematic call?

Thanks.

Daniele Giordano · ‎01-19-2011

Your analysis is right.

The RFC3261 mandates the Via branch in every request.
The first version of SIP described in RFC2543 did not mandate the Via
branch. Normally, software without Via branch still works because the RFC3261
mandates backward compatibility.

So, probably the IOS 12.3 has a limitation or bug.
Even if the dial-peer shows "session protocol sipv2" the brach header is missing.

Does your sip proxy support RFC2543?

Regards.

nawfeloujdi · ‎01-19-2011

*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructTDUsrContainer: usrContainer[0x
63426774], magic[FACE0FFF]
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x63426774, tagID=6, dataSize=16, instID=-1,modifier=1
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x6337F050], nxtElem[0x0], magic[0xFACE0FFF] tagID[6], dataLen[16], modif[1]
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x6337F050] instID[-1] into container[0x63426774]
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer:
container=0x63426774, tagID=9, dataSize=1, instID=-1,modifier=1
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x6337AB00], nxtElem[0x0], magic[0xFACE0FFF] tagID[9], dataLen[1], modif[1]
*Jan 19 16:00:18.695: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x6337AB00] instID[-1] into container[0x63426774]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x63426774, tagID=14, dataSize=1, instID=-1,modifier=1
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x6337AB50], nxtElem[0x0], magic[0xFACE0FFF] tagID[14], dataLen[1], modif[1]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x6337AB50] instID[-1] into container[0x63426774]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer: container=0x63426774, tagID=17, dataSize=22, instID=-1,modifier=1
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x6337ABA0], nxtElem[0x0], magic[0xFACE0FFF] tagID[17], dataLen[22], modif[1]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x6337ABA0] instID[-1] into container[0x63426774]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilAddDataToUsrContainer:
container=0x63426774, tagID=19, dataSize=4, instID=0,modifier=1
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x6337AC04], nxtElem[0x0], magic[0xFACE0FFF] tagID[19], dataLen[4], modif[1]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToContainer: Adding tdObject[0x6337AC04] instID[0] into container[0x63426774]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructMultiInstHolderObject: multiHolder[0x6337AC58], nxtElem[0x0], magic[0xFACE0FFF], tagID[19], dataLen[0], modif[-1], numInst[0]
*Jan 19 16:00:18.699: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtPushInstToMultiInstHolder:
Successful in pushing instance object[0x6337AC04] into holder[0x6337AC58]
*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/cc_api_display_ie_subfields:
*Jan 19 16:00:19.067: cc_api_call_setup_ind:
*Jan 19 16:00:19.067: cisco-username=
*Jan 19 16:00:19.067: ----- ccCallInfo IE subfields -----
*Jan 19 16:00:19.067: cisco-ani=911873699
*Jan 19 16:00:19.067: cisco-anitype=2
*Jan 19 16:00:19.067: cisco-aniplan=1
*Jan 19 16:00:19.067: cisco-anipi=0
*Jan 19 16:00:19.067: cisco-anisi=1
*Jan 19 16:00:19.067: dest=911111500
*Jan 19 16:00:19.067: cisco-desttype=2
*Jan 19 16:00:19.067: cisco-destplan=1
*Jan 19 16:00:19.067: cisco-rdn=
*Jan 19 16:00:19.067: cisco-rdntype=-1
*Jan 19 16:00:19.067: cisco-rdnplan=-1
*Jan 19 16:00:19.067: cisco-rdnpi=-1
*Jan 19 16:00:19.067: cisco-rdnsi=-1
*Jan 19 16:00:19.067: cisco-redirectreason=-1

*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind: (vdbPtr=0x63003B00, callInfo={called=911111500,called_oct3=0xA1,calling=911873699,calling_oct3=0x21,calling_oct3a=0x81,calling_xlated=false,subscriber_type_str=RegularLine,fdest=1,peer_tag=101, prog_ind=0,callingIE_present 1, src_route_label=Orange, tgt_route_label= clid_transparent=0},callID=0x63445B64)
*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/cc_api_call_setup_ind:
type 4 , prot 0
*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.067: ccCheckClipClir: calling number is: "911873699", calling oct3a is: 0x81
*Jan 19 16:00:19.067: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.067: Calling Party number is User Provided
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.071: Leaving ccCheckClipClir
   calling number is: "911873699"
   calling oct3 is: 0x21
   calling oct3a is: 0x81
*Jan 19 16:00:19.071: //1/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: Increment call volume:

*Jan 19 16:00:19.071: //1/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: current call volume: 1
*Jan 19 16:00:19.071: //1/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: entry's incoming TRUE.
*Jan 19 16:00:19.071: //1/xxxxxxxxxxxx/CCAPI/cc_insert_call_entry: is_incoming is TRUE
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructHashProfileTab: profileTable[0x62959A50], numBuckets[11], numEntries[0]
*Jan 19 16:00:19.071: //1/0BE869DB83AA/CCAPI/ccTDPvtProfileTableBuildManager: Invoking necessary profileTable updaters...
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: Updating profileTable[0x62959A50] with objects in container[0x63426774]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer:
obtained key[5] for the tag[6]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62959A50], tdObject[0x6337F050]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[7] for the tag[9]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62959A50], tdObject[0x6337AB00]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[3] for the tag[14]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62959A50], tdObject[0x6337AB50]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[0] for the tag[17]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62959A50], tdObject[0x6337ABA0]
*Jan 19 16:00:19.071: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtUpdateProfileTabFromContainer: obtained key[6] for the tag[19]
*Jan 19 16:00:19.075: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62959A50], tdObject[0x6337AC58]
*Jan 19 16:00:19.075: //1/0BE869DB83AA/CCAPI/ccTDPvtProfileTableBuildManager:
*Jan 19 16:00:19.075: ccTDUtilDumpAllElemInProfileTab: profileTable[0x62959A50], numBuckets[11], numEntries[5]
*Jan 19 16:00:19.075: Bucket { 0 } ------>0x6337ABA0[0x0,t-17,l-22,d-0x6337ABC0,m-1,u-11259,g-FACE0FFF]
*Jan 19 16:00:19.075:
*Jan 19 16:00:19.075: Bucket { 3 } ------>0x6337AB50[0x0,t-14,l-1,d-0x6337AB70,m-1,u-11259,g-FACE0FFF]
*Jan 19 16:00:19.075:
*Jan 19 16:00:19.075: Bucket { 5 } ------>0x6337F050[0x0,t-6,l-16,d-0x6337F070,m-1,u-11259,g-FACE0FFF]
*Jan 19 16:00:19.075:
*Jan 19 16:00:19.075: Bucket { 6 } ------>0x6337AC58[0x0,t-19,m-1,g-FACE0FFF 0x6337AC04,i-0 ]
*Jan 19 16:00:19.075:
*Jan 19 16:00:19.075: Bucket { 7 } ------>0x6337AB00[0x0,t-9,l-1,d-0x6337AB20,m-1,u-11259,g-FACE0FFF]
*Jan 19 16:00:19.075:
*Jan 19 16:00:19.075: //-1/xxxxxxxxxxxx/CCAPI/ccTDDestructTDUsrContainer: Container[0x63426774]
*Jan 19 16:00:19.075: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: not the VoIP or MMoIP
*Jan 19 16:00:19.079: //1/0BE869DB83AA/CCAPI/cc_process_call_setup_ind: (event=0x62B42AF8)
*Jan 19 16:00:19.079: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_registration_lookup: matching parameters - called# [911111500], calling# [911873699], consultid []
*Jan 19 16:00:19.079: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_match_search: Searching for node with called# [911111500], calling# [911873699], consultid []
*Jan 19 16:00:19.079: //-1/xxxxxxxxxxxx/CCAPI/cc_setupind_registration_lookup:
No matching node
*Jan 19 16:00:19.079: //1/0BE869DB83AA/CCAPI/cc_process_call_setup_ind: >>>>CCAPI handed cid 1 with tag 101 to app "DEFAULT"
*Jan 19 16:00:19.079: //1/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(24=CC_EV_CALL_SETUP_IND), cid(1), disp(0)
*Jan 19 16:00:19.079: //1/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(SSA_EV_CALL_SETUP_IND), cid(1), disp(0)
*Jan 19 16:00:19.079: //1/xxxxxxxxxxxx/SSAPP:-1:-1/ssaCallSetupInd:
*Jan 19 16:00:19.083: //1/0BE869DB83AA/CCAPI/ccCallSetContext: (callID=0x1, context=0x62956720)
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaCallSetupInd: cid(1), st(SSA_CS_MAPPING),oldst(0), ev(24)ev->e.evCallSetupInd.nCallInfo.finalDestFlag = 1
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaCallSetupInd: src route label=Orange, tgt route label= tg_label_flag 0x0
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaCallSetupInd: finalDest cllng(911873699), clled(911111500) tgt_route_label()tg_label_flag 0x0
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaCallSetupInd: cid(1), st(SSA_CS_CALL_SETTING),oldst(0), ev(24)dpMatchPeersMoreArg result= 0
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaDebugPeers: ssaSetupPeer cid(1) peer list: tag(501) called number (911111500)
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaSetupPeer: dialpeer tags in rotary= 501
*Jan 19 16:00:19.083: //1/0BE869DB83AA/SSAPP:101:-1/ssaSetupPeer: cid(1), destPat(911111500), matched(2), prefix(om.es), peer(63213AB4), peer->encapType (2)
*Jan 19 16:00:19.083: //1/0BE869DB83AA/CCAPI/ccCallProceeding: (callID=0x1, prog_ind=0x0)
*Jan 19 16:00:19.083: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest: (Inbound call = 0x1, outbound peer =501, dest=,
             params=0x62B56568 mode=0, *callID=0x62B56B38, prog_ind = 0callingIE_present 1)
*Jan 19 16:00:19.083: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest:
*Jan 19 16:00:19.083: ccCallSetupRequest numbering_type 0xA1
*Jan 19 16:00:19.083: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest:
*Jan 19 16:00:19.087: ccCallSetupRequest: calling number is:911873699

*Jan 19 16:00:19.087: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest: calling oct3a is:0x81

*Jan 19 16:00:19.087: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.087: ccCheckClipClir: calling number is: "911873699", calling oct3a is: 0x81
*Jan 19 16:00:19.087: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.087: Calling Party number is User Provided
*Jan 19 16:00:19.087: //-1/xxxxxxxxxxxx/CCAPI/ccCheckClipClir:
*Jan 19 16:00:19.087: Leaving ccCheckClipClir
   calling number is: "911873699"
   calling oct3 is: 0x21
   calling oct3a is: 0x81
*Jan 19 16:00:19.087: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest: after ccCheckClipClir - calling oct3a is:0x81

*Jan 19 16:00:19.087: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest: dest pattern ^.........$, called 911111500, digit_strip 0
*Jan 19 16:00:19.087: //1/0BE869DB83AA/CCAPI/ccCallSetupRequest:
*Jan 19 16:00:19.087: callingNumber=911873699, calledNumber=911111500, redirectNumber= display_info= calling_oct3a=81
*Jan 19 16:00:19.087: accountNumber=, finalDestFlag=1,
guid=0be8.69db.231c.11e0.83aa.c83f.4fb0.3721
*Jan 19 16:00:19.087: peer_tag=501
*Jan 19 16:00:19.087: //-1/xxxxxxxxxxxx/CCAPI/cc_api_display_ie_subfields:
*Jan 19 16:00:19.087: ccCallSetupRequest:
*Jan 19 16:00:19.087: cisco-username=
*Jan 19 16:00:19.087: ----- ccCallInfo IE subfields -----
*Jan 19 16:00:19.087: cisco-ani=911873699
*Jan 19 16:00:19.087: cisco-anitype=2
*Jan 19 16:00:19.087: cisco-aniplan=1
*Jan 19 16:00:19.087: cisco-anipi=0
*Jan 19 16:00:19.087: cisco-anisi=1
*Jan 19 16:00:19.087: dest=911111500
*Jan 19 16:00:19.087: cisco-desttype=2
*Jan 19 16:00:19.087: cisco-destplan=1
*Jan 19 16:00:19.087: cisco-rdn=
*Jan 19 16:00:19.087: cisco-rdntype=-1
*Jan 19 16:00:19.087: cisco-rdnplan=-1
*Jan 19 16:00:19.087: cisco-rdnpi=-1
*Jan 19 16:00:19.087: cisco-rdnsi=-1
*Jan 19 16:00:19.087: cisco-redirectreason=-1

*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbPtr=0x628FA9E0, dest=, callParams={called=911111500,called_oct3=0xA1, calling=911873699,calling_oct3=0x21, calling_oct3a= 0x81, calling_xlated=f
dest=1, voice_peer_tag=501},mode=0x0, appl_call_id=, callingIE_present=1)
*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Jan 19 16:00:19.091: ccIFCallSetupRequestPrivate: src route label Orange tgt route label tg_label_flag 0x0

*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: vdbPtr type = 3
*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate: (vdbPtr=0x628FA9E0, dest=, callParams={called=911111500, called_oct3 0xA1, calling=911873699,calling_oct3 0x21, calling_oct3a 0x81, calling_xlated=false, fdest=1, voice_peer_tag=501}, mode=0x0, xltrc=-5)
*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/CCAPI/ccIFCallSetupRequestPrivate:
*Jan 19 16:00:19.091: //2/0BE869DB83AA/CCAPI/cc_insert_call_entry: not incoming entry
*Jan 19 16:00:19.091: //2/0BE869DB83AA/CCAPI/cc_insert_call_entry: entry's incoming FALSE.
*Jan 19 16:00:19.091: //2/0BE869DB83AA/CCAPI/cc_insert_call_entry:
is_incoming is FALSE
*Jan 19 16:00:19.091: //-1/xxxxxxxxxxxx/CCAPI/cc_set_voice_port_value:
*Jan 19 16:00:19.091: callParams->spi_info is NULL
*Jan 19 16:00:19.091: //1/0BE869DB83AA/CCAPI/ccSaveDialpeerTag: (callID=0x1, dialpeer_tag=501)
*Jan 19 16:00:19.091: //2/0BE869DB83AA/CCAPI/ccCallSetContext: (callID=0x2, context=0x62957790)
*Jan 19 16:00:19.091: //1/0BE869DB83AA/CCAPI/ccCallReportDigits: (callID=0x1, enable=0x0)
*Jan 19 16:00:19.091: //1/0BE869DB83AA/CCAPI/cc_api_call_report_digits_done: (vdbPtr=0x63003B00, callID=0x1, disp=0)
*Jan 19 16:00:19.091: //1/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(56=CC_EV_CALL_REPORT_DIGITS_DONE), cid(1), disp(0)
*Jan 19 16:00:19.095: //1/0BE869DB83AA/SSAPP:101:-1/ssaTraceSct: cid(1)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_REPORT_DIGITS_DONE)
oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(1)fDest(1)
*Jan 19 16:00:19.095: //1/0BE869DB83AA/SSAPP:101:-1/ssaTraceSct: -cid2(2)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_MAPPING)
*Jan 19 16:00:19.095: //1/0BE869DB83AA/SSAPP:101:-1/ssaDebugPeers: ssaReportDigitsDone cid(1) peer list: (empty)
*Jan 19 16:00:19.095: //1/0BE869DB83AA/SSAPP:101:-1/ssaReportDigitsDone: callid=1 Reporting disabled.
*Jan 19 16:00:19.095: //-1/xxxxxxxxxxxx/CCAPI/ccTDUtilSetDataInstance: Setting data for callID[2], tagID[20], instID[-1], data[0x62BE6518], dataSize[28]
*Jan 19 16:00:19.095: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructInstanceTDObject: tdObject[0x62959CBC], nxtElem[0x0], magic[0xFACE0FFF] tagID[20], dataLen[28], modif[3]
*Jan 19 16:00:19.099: //-1/xxxxxxxxxxxx/CCAPI/ccTDConstructHashProfileTab: profileTable[0x62958028], numBuckets[11], numEntries[0]
*Jan 19 16:00:19.099: //2/0BE869DB83AA/CCAPI/ccTDPvtProfileTableBuildManager: Invoking necessary profileTable updaters...
*Jan 19 16:00:19.099: //-1/xxxxxxxxxxxx/CCAPI/ccTDPvtAddObjectToProfileBucket: profileTable[0x62958028], tdObject[0x62959CBC]
*Jan 19 16:00:19.099: //2/0BE869DB83AA/CCAPI/ccTDPvtProfileTableBuildManager:
*Jan 19 16:00:19.099: ccTDUtilDumpAllElemInProfileTab: profileTable[0x62958028], numBuckets[11], numEntries[1]
*Jan 19 16:00:19.099: Bucket { 1 } ------>0x62959CBC[0x0,t-20,l-28,d-0x62959CDC,m-3,u-11260,g-FACE0FFF]
*Jan 19 16:00:19.099:
*Jan 19 16:00:19.099: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: remote IP is 0.0.0.0
*Jan 19 16:00:19.099: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: hwidb is FastEthernet0
*Jan 19 16:00:19.099: //-1/xxxxxxxxxxxx/CCAPI/cc_incr_if_call_volume: create entry in list: 1
*Jan 19 16:00:19.099: //2/0BE869DB83AA/CCAPI/cc_api_call_proceeding: (vdbPtr=0x628FA9E0, callID=0x2,
       prog_ind=0x0)
*Jan 19 16:00:19.103: //2/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(21=CC_EV_CALL_PROCEEDING), cid(2), disp(0)
*Jan 19 16:00:19.103: //2/0BE869DB83AA/SSAPP:0:-1/ssaTraceSct: cid(2)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_PROCEEDING)
oldst(SSA_CS_MAPPING)cfid(-1)csize(0)in(0)fDest(0)
*Jan 19 16:00:19.103: //2/0BE869DB83AA/SSAPP:0:-1/ssaTraceSct: -cid2(1)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)
*Jan 19 16:00:19.103: //2/0BE869DB83AA/SSAPP:0:-1/ssaCallProc:
*Jan 19 16:00:19.103: //1/0BE869DB83AA/CCAPI/ccGetDialpeerTag: (callID=0x1)
*Jan 19 16:00:19.107: //2/0BE869DB83AA/SSAPP:0:-1/ssaIgnore: cid(2), st(SSA_CS_CALL_SETTING),oldst(1), ev(21)
*Jan 19 16:00:19.247: //2/0BE869DB83AA/CCAPI/cc_api_call_connected: (vdbPtr=0x628FA9E0, callID=0x2), prog_ind = 0, cData->bitmask=0x0
*Jan 19 16:00:19.247: //2/0BE869DB83AA/CCAPI/cc_api_call_connected: setting callEntry->connected to TRUE

*Jan 19 16:00:19.251: //2/xxxxxxxxxxxx/SSAPP:-1:-1/sess_appl: ev(8=CC_EV_CALL_CONNECTED), cid(2), disp(0)
*Jan 19 16:00:19.251: //2/0BE869DB83AA/SSAPP:0:-1/ssaTraceSct: cid(2)st(SSA_CS_CALL_SETTING)ev(SSA_EV_CALL_CONNECTED)
oldst(SSA_CS_CALL_SETTING)cfid(-1)csize(0)in(0)fDest(0)
*Jan 19 16:00:19.251: //2/0BE869DB83AA/SSAPP:0:-1/ssaTraceSct: -cid2(1)st2(SSA_CS_CALL_SETTING)oldst2(SSA_CS_CALL_SETTING)
*Jan 19 16:00:19.251: //2/0BE869DB83AA/SSAPP:0:-1/ssaConnect:
*Jan 19 16:00:19.251: //1/0BE869DB83AA/CCAPI/ccGetDialpeerTag: (callID=0x1)
*Jan 19 16:00:19.251: //1/0BE869DB83AA/CCAPI/ccConferenceCreate: (confID=0x62B56C4C, callID1=0x1, callID2=0x2, tag=0x0)
*Jan 19 16:00:19.251: //1/0BE869DB83AA/CCAPI/ccConferenceCreate: (pConf=0x622EFBE0)
*Jan 19 16:00:19.251: //2/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done: (confID=0x1, srcIF=0x628FA9E0, srcCallID=0x2, dstCallID=0x1, disposition=0, tag=0x0)
*Jan 19 16:00:19.255: //1/xxxxxxxxxxxx/CCAPI/cc_api_bridge_done: (confID=0x1, srcIF=0x63003B00, srcCallID=0x1, dstCallID=0x2, disposition=0, tag=0x0)
*Jan 19 16:00:19.255: //1/0BE869DB83AA/CCAPI/cc_api_caps_ind: (dstVdbPtr=0x628FA9E0, dstCallId=0x2, srcCallId=0x1,
      caps={codec=0x6EFF7, fax_rate=0xFF, vad=0x3, modem=0x2
            codec_bytes=20, signal_type=2})
*Jan 19 16:00:19.255: //1/0BE869DB83AA/CCAPI/cc_api_caps_ind: (Playout: mode 1, initial 60, min 40, max 250, fax 300)
*Jan 19 16:00:19.255: //2/0BE869DB83AA/CCAPI/cc_api_caps_ind: (dstVdbPtr=0x63003B00, dstCallId=0x1, srcCallId=0x2,
      caps={codec=0x4, fax_rate=0x2, vad=0x1, modem=0x0
            codec_bytes=20, signal_type=1})
*Jan 19 16:00:19.255: //2/0BE869DB83AA/CCAPI/cc_api_caps_ind: (Playout: mode 1, initial 60, min 40, max 250, fax 300)
*Jan 19 16:00:19.255: //2/0BE869DB83AA/CCAPI/cc_api_caps_ack: (dstVdbPtr=0x63003B00, dstCallId=0x1, srcCallId=0x2,
      caps={codec=0x4, fax_rate=0x2, vad=0x1, modem=0x0
            codec_bytes=20, signal_type=1, seq_num_start=7923})
*Jan 19 16:00:19.255: //1/0BE869DB83AA/CCAPI/cc_api_caps_ack: (dstVdbPtr=0x628FA9E0, dstCallId=0x2, srcCallId=0x1,
      caps={codec=0x4, fax_rate=0x2, vad=0x1, modem=0x0
            codec_b
(END)