Basic h323 calling between Ip Office broken 8.0.44?

[kewl99]

Hi All, I have two IP 500 at version 8.0.44, tried setting up basic H323 trunk calling between systems, not using SCN(they have conflicting extensions at both sites and don't want to change). I have H323 trunks pointed to each system and a shortcode 8xxx, feature dial, telephone number N, pointed to H323 trunk id #. I have 8 channels of networking licenses. When I dial i get number busy, in monitor it shows that can't find extension name and releases call? Never had a issue with this before, is it something that is broken in this version of software? Anyone else come across this?

ACSS - (SME)

 

[amriddle01]

Post the trace, but for testing create a non clashing extn number/group and see if you can dial that

 

[kewl99]

Here is a copy of the trace, called extension 3000

185620696mS ISDNL3Evt: v=10 p1=10,p2=1001,p3=5,p4=0,s1=
185621252mS H323Rx: 27 src=10.5.40.251:4117
H323 Pcol=08(Q931) Reflen=2 ref=0016(Remote)
Message Type = Setup

185621252mS H323Rx: src=10.5.40.251:4117
H323 Pcol=08(Q931) Reflen=2 ref=0016(Remote)
Message Type = Setup
InformationElement = BearerCapability
0000 04 03 80 90 a2 .....
InformationElement = Display
0000 28 10 53 65 72 76 65 72 20 52 6f 6f 6d 3e 33 30 (.Server Room>30
0010 30 30 00
InformationElement = CallingPartyNumber
0000 6c 05 80 35 32 30 33 l..5203
InformationElement = CalledPartyNumber
0000 70 05 80 33 30 30 30 p..3000
InformationElement = Sending Complete
InformationElement = FAC
0000 1c 22 9f aa 06 80 01 00 82 01 00 8b 01 00 a1 14 ."..............
0010 02 02 39 36 02 01 00 80 0b 53 65 72 76 65 72 20 ..96.....Server
0020 52 6f 6f 6d Room
InformationElement = UU
0000 7e 00 85 05 20 b8 06 00 08 91 4a 00 05 01 40 0a ~... .....J...@.
0010 00 53 00 65 00 72 00 76 00 65 00 72 00 20 00 52 .S.e.r.v.e.r. .R
0020 00 6f 00 6f 00 6d 22 c0 b4 00 2a 00 08 49 50 20 .o.o.m"...*..IP
0030 35 30 30 20 56 32 07 38 2e 30 20 28 34 34 29 00 500 V2.8.0 (44).
0040 01 01 80 63 33 00 0a 04 28 f8 06 b8 00 99 03 a6 ...c3...(.......
0050 00 e8 ac 11 da 8b 0b 00 e0 07 00 00 0d 00 d5 0d ................
0060 80 00 07 00 0a 05 28 fb 10 15 11 00 99 03 a6 00 ......(.........
0070 e8 ac 11 da 8b 0c 00 e0 07 00 00 0d 01 00 01 80 ................
0080 01 00 01 00 10 80 01 80 ........
UserInformation = {
h323-uu-pdu = {
h323-message-body = setup = {
protocolIdentifier = 0.0.8.2250.0.5
sourceAddress = { 1 item(s)
[0] = h323-ID =
0053 0065 0072 0076 0065 0072 0020 0052 Server R
006f 006f 006d oom
}
sourceInfo = {
vendor = {
vendor = {
t35CountryCode = 180
t35Extension = 0
manufacturerCode = 10752
}
productId =
49 50 20 35 30 30 20 56 32 IP 500 V2
versionId =
38 2e 30 20 28 34 34 29 8.0 (44)
}
terminal = {
}
mc = false
undefinedNode = false
}
destinationAddress = { 1 item(s)
[0] = dialedDigits =
33 30 30 30 3000
}
destCallSignalAddress = ipAddress = {
ip =
0a 04 28 f8 ..(.
port = 1720
}
activeMC = false
conferenceID =
99 03 a6 00 e8 ac 11 da 8b 0b 00 e0 07 00 00 0d ................
conferenceGoal = create
callType = pointToPoint
sourceCallSignalAddress = ipAddress = {
ip =
0a 05 28 fb ..(.
port = 4117
}
callIdentifier = {
guid =
99 03 a6 00 e8 ac 11 da 8b 0c 00 e0 07 00 00 0d ................
}
mediaWaitForConnect = false
canOverlapSend = true
multipleCalls = false
maintainConnection = false
}
h245Tunneling = true
}
}
185621252mS H323Evt: Didn't find extension by name
185621252mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1
185621253mS H323Tx: 0 dst=10.5.40.251:4117
H323 Pcol=08(Q931) Reflen=2 ref=0016(Local)
Message Type = ReleaseComplete

185621253mS H323Tx: dst=10.5.40.251:4117
H323 Pcol=08(Q931) Reflen=2 ref=0016(Local)
Message Type = ReleaseComplete
InformationElement = CAUSE
0000 08 02 80 91 ....
InformationElement = UU
0000 7e 00 23 05 25 c0 06 00 08 91 4a 00 05 58 88 00 ~.#.%.....J..X..
0010 11 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
0020 00 00 10 80 01 80 ......
UserInformation = {
h323-uu-pdu = {
h323-message-body = releaseComplete = {
protocolIdentifier = 0.0.8.2250.0.5
reason = undefinedReason
callIdentifier = {
guid =
00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................
}
}
h245Tunneling = true
}
}


ACSS - (SME)

 

[hairlessupportmonkey]

are the switches named the same? how are they connected? whats the IPs of both switches?

ACSS - SME
General Geek

 

[amriddle01]

Can we have a nice trace with all default options, that one is hard to read

 

[kewl99]

switches are not named the same, one is 10.4.40.248 the other 10.5.40.251, they are connected by MPLS circuit between sites, private network

ACSS - (SME)

 

[kewl99]

187217212mS LIC: Processing token (serial number=1317245565)
187217212mS LIC: ProcessToken (Serial number = 1317245565)
187220109mS H323Rx: 28 src=10.5.40.251:4118
H323 Pcol=08(Q931) Reflen=2 ref=0017(Remote)
Message Type = Setup

187220109mS H323Evt: Didn't find extension by name
187220109mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1
187220110mS H323Tx: 0 dst=10.5.40.251:4118
H323 Pcol=08(Q931) Reflen=2 ref=0017(Local)
Message Type = ReleaseComplete


ACSS - (SME)

 

[tlpeter]

Please turn of the H323 stuff it does not show what we need to see.
Just a default trace.

BAZINGA!

I'm not insane, my mother had me tested!

 

[kewl99]

trace from calling system..

75785098mS CMExtnEvt: Server Room: Recover Timer reason=CMTRWrapUp
75785098mS CMExtnEvt: v=30 State, new=Idle old=PortRecoverDelay,0,0,Server Room
75785099mS CMExtnTx: v=5203, p1=0
CMVoiceMailStatus
Line: type=DigitalExtn 7 Call: lid=0 id=-1 in=0
Called[Server Room Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [Server Room Msgs=0]
Timed: 21/07/12 10:27
75799617mS PRN: 5203: Digit Pressed 8
75799618mS CMCallEvt: 0.1116.0 -1 BaseEP: NEW CMEndpoint f5075768 TOTAL NOW=1 CALL_LIST=0
75799618mS CMCallEvt: 0.1116.0 -1 Server Room.-1: NEW CMExtnEndpoint f5075768, Name=Server Room, Extn=5203, Phys Extn=286
75799619mS CMCallEvt: CREATE CALL:40 (f5075238)
75799619mS CMCallEvt: 0.1117.0 -1 BaseEP: NEW CMEndpoint f5073d74 TOTAL NOW=2 CALL_LIST=0
75799621mS CMExtnEvt: Server Room: CMExtnHandler::SetCurrent( id: 0->1116 )
75799621mS CMExtnRx: v=5203, p1=0
CMSetup
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[5203] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Server Room
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Server Room
75799621mS CMCallEvt: 0.1116.0 40 Server Room.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
75799621mS CMExtnEvt: v=30 State, new=Dialling old=Idle,0,0,Server Room
75799622mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=5203 dir=out complete=0 ses=0
75799622mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
75799622mS CMCallEvt: 0.1116.0 40 Server Room.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
75799623mS CMExtnTx: v=5203, p1=0
CMSetupAck
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
BChan: slot=9 chan=32
Timed: 21/07/12 10:28
75799624mS CMExtnRx: v=5203, p1=0
CMInformation
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[8] Type=Default (100) Reason=CMDRdirect
75799624mS CMTARGET: 0.1116.0 40 Server Room.0: Setting Hard Timer 4000
75799624mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=8 sub= calling=5203 dir=out complete=0 ses=0
75799624mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=8 type=100 depth=1 nobar=1 setorig=1 ses=0
75799625mS CD: CALL: 0.1116.0 BState=Idle Cut=0 Music=0.0 Aend="Server Room(5203)" (9.32) Bend="" [] (0.0) CalledNum=8 () CallingNum=5203 (Server Room) Internal=1 Time=6 AState=Dialling
75800082mS PRN: 5203: Digit Pressed 3
75800082mS CMExtnRx: v=5203, p1=0
CMInformation
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[3] Type=Default (100) Reason=CMDRdirect
75800083mS CMTARGET: 0.1116.0 40 Server Room.0: Setting Hard Timer 4000
75800083mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=83 sub= calling=5203 dir=out complete=0 ses=0
75800083mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=83 type=100 depth=1 nobar=1 setorig=1 ses=0
75800092mS RES: Sat 21/7/2012 10:28:06 FreeMem=59947916(1) CMMsg=4 (6) Buff=5200 959 997 7343 5 Links=888
75800092mS RES2: IP 500 V2 8.0(44) Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=66 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=15 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
75800657mS PRN: 5203: Digit Pressed 0
75800657mS CMExtnRx: v=5203, p1=0
CMInformation
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
75800658mS CMTARGET: 0.1116.0 40 Server Room.0: Setting Hard Timer 4000
75800658mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=830 sub= calling=5203 dir=out complete=0 ses=0
75800658mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=830 type=100 depth=1 nobar=1 setorig=1 ses=0
75800907mS PRN: 5203: Digit Pressed 0
75800907mS CMExtnRx: v=5203, p1=0
CMInformation
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
75800908mS CMTARGET: 0.1116.0 40 Server Room.0: Setting Hard Timer 4000
75800908mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=8300 sub= calling=5203 dir=out complete=0 ses=0
75800908mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=8300 type=100 depth=1 nobar=1 setorig=1 ses=0
75801220mS PRN: 5203: Digit Pressed 0
75801220mS CMExtnRx: v=5203, p1=0
CMInformation
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Called[0] Type=Default (100) Reason=CMDRdirect
75801221mS CMTARGET: 0.1116.0 40 Server Room.0: Setting Hard Timer 4000
75801221mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=83000 sub= calling=5203 dir=out complete=0 ses=0
75801221mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=83000 type=100 depth=1 nobar=1 setorig=1 ses=0
75805220mS CMTARGET: 0.1116.0 40 Server Room.0: TimerExpired cause=CMTCDelayedProcessing
75805220mS CMTARGET: 0.1116.0 40 Server Room.0: LOOKUP CALL ROUTE: type=100 called_party=83000 sub= calling=5203 dir=out complete=1 ses=0
75805220mS CMTARGET: 0.1116.0 40 Server Room.0: ADD TARGET (N): number=83000 type=100 depth=1 nobar=1 setorig=1 ses=0
75805221mS CMTARGET: 0.1116.0 40 Server Room.0: SYS SC: 83000 3 3000 sc=type=Dial code=8N;, num=N callinfop->sending_complete=1 secondary_dialtone=
75805221mS CMARS: FindActiveARSByGroupID GroupID=91 - Not Found
75805221mS CMLRQ: FindActiveLRQByGroupID GroupID=91 - Not Found
75805222mS CMTARGET: Group Id: 91 has NOT been found in Line: 9
75805222mS CMTARGET: Group Id: 91 has NOT been found in Line: 10
75805222mS CMTARGET: Group Id: 91 has NOT been found in Line: 13
75805222mS CMMap: a=0.18 b=0.0 Mapper::AllocateCodec allocated CMRTVocoder resource busy 1, total 20
75805223mS CMCallEvt: 0.1118.0 -1 BaseEP: NEW CMEndpoint f506b2ac TOTAL NOW=3 CALL_LIST=1
75805225mS CMTARGET: DIAL LINE: 40 GROUP = 91 SUCCESS = f506b2ac
75805226mS CMTARGET: 0.1116.0 40 Server Room.0: INITIAL TARGETING SUCCEEDED
75805226mS CMTARGET: 0.1116.0 40 Server Room.0: GetNoAnswerTimer:15
75805226mS CMCallEvt: 0.1116.0 40 Server Room.0: StateChange: END=A CMCSDialling->CMCSDialled
75805226mS CMExtnEvt: v=30 State, new=Proceeding old=Dialling,0,0,Server Room
75805226mS CMExtnTx: v=5203, p1=0
CMProceeding
Line: type=DigitalExtn 7 Call: lid=0 id=1116 in=0
Timed: 21/07/12 10:28
75805227mS CMCallEvt: 0.1117.0 40 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
75805228mS CMCallEvt: 0.1118.0 40 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
75805228mS CMLineTx: v=91
CMSetup
Line: type=IPLine 91 Call: lid=0 id=1118 in=0
Called[3000] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[5203] Type=Unknown Plan=Unknown
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIESupplementaryService (3)
Network Facility Extension
sourceEntity: 0
destinationEntity: 0
Interpretation APDU
discardAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 14651
user 'Server Room' presentation Allowed
IE CMIECallSignalChannelData (8) unknown
Display [Server Room>3000]
Timed: 21/07/12 10:28
Locale: enu
75805229mS CD: CALL: 0.1116.0 BState=Idle Cut=1 Music=0.0 Aend="Server Room(5203)" (9.32) Bend="Line 91" [Line 91] (0.0) CalledNum=83000 () CallingNum=5203 (Server Room) Internal=0 Time=5610 AState=Dialled
75805230mS H323Evt: v=0 stacknum=91 State, new=NullState, old=NullState id=-1
75805231mS H323Evt: v=0 stacknum=91 State, new=Initiated, old=NullState id=1118
75805240mS H323Evt: v=0 stacknum=91 State, new=NullState, old=Initiated id=1118
75805241mS CMLineRx: v=91
CMReleaseComp
Line: type=IPLine 91 Call: lid=0 id=1118 in=0
Cause=17, User busy
75805241mS CMCallEvt: 0.1117.0 40 TargetingEP: RequestEnd 0.1118.0 40 H323TrunkEP
75805242mS CMTARGET: 0.1116.0 40 Server Room.0: CancelTimer CMTCNoAnswerTimeout
75805242mS CMCallEvt: 0.1117.0 -1 BaseEP: DELETE CMEndpoint f5073d74 TOTAL NOW=2 CALL_LIST=1
75805242mS CMCallEvt: 0.1118.0 40 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSCompleted
75805244mS CMLOGGING: CALL:2012/07/2110:28,00:00:00,000,5203,O,3000,83000,ServerRoom,,,0,,""n/a,0
75805244mS CD: CALL: 0.1116.0 BState=Disconnecting Cut=1 Music=0.0 Aend="Server Room(5203)" (9.32) Bend="Line 91" [Line 91] (341.1) CalledNum=3000 () CallingNum=5203 (Server Room) Internal=0 Time=5625 AState=Dialled
75805245mS CD: CALL: 0.1116.0 Deleted
75805245mS CMExtnEvt: Server Room: CALL LOST (CMCauseBusy)
75805245mS CMExtnEvt: Server Room: Extn(5203) Calling Party Number(5203) Type(CMNTypeInternal)
75805246mS CMCallEvt: 0.1116.0 -1 Server Room.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
75805246mS CMExtnEvt: v=30 State, new=CMESCompleted old=Proceeding,0,0,Server Room
75805247mS CMCallEvt: 0.1118.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
75805247mS CMCallEvt: END CALL:40 (f5075238)
75805248mS CMCallEvt: 0.1118.0 -1 BaseEP: DELETE CMEndpoint f506b2ac TOTAL NOW=1 CALL_LIST=0
75805250mS CMMap: a=0.18 b=0.0 Mapper::FreeCodec freed CMRTVocoder resource busy 0, total 20
75805251mS CMMap: a=9.32 b=0.0 B1
75805592mS RES: Sat 21/7/2012 10:28:11 FreeMem=59956996(1) CMMsg=4 (6) Buff=5200 960 999 7343 5 Links=883
75805592mS RES2: IP 500 V2 8.0(44) Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=72 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=16 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
75805751mS CMMap: a=9.32 b=0.0 B0
75806251mS CMMap: a=9.32 b=0.0 B1
75806751mS CMMap: a=9.32 b=0.0 B0
75807251mS CMMap: a=9.32 b=0.0 B1
75807751mS CMMap: a=9.32 b=0.0 B0
75808251mS CMMap: a=9.32 b=0.0 B1
75808751mS CMMap: a=9.32 b=0.0 B0
75809251mS CMMap: a=9.32 b=0.0 B1
75809647mS ISDNL3Evt: v=9 p1=9,p2=1001,p3=5,p4=0,s1=
75809647mS ISDNL3Evt: v=10 p1=10,p2=1001,p3=5,p4=0,s1=
75809650mS ISDNL3Evt: v=13 p1=13,p2=1001,p3=5,p4=0,s1=
75809751mS CMMap: a=9.32 b=0.0 B0
75810251mS CMMap: a=9.32 b=0.0 B1
75810592mS RES: Sat 21/7/2012 10:28:16 FreeMem=59958864(1) CMMsg=4 (6) Buff=5200 960 1000 7343 5 Links=884
75810592mS RES2: IP 500 V2 8.0(44) Tasks=47 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=67 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=15 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
75810751mS CMMap: a=9.32 b=0.0 B0

********** Warning: Logging to Screen Stopped **********

trace from receiving system..

189464004mS ISDNL3Evt: v=10 p1=10,p2=1001,p3=5,p4=0,s1=
189464911mS H323Evt: Didn't find extension by name
189464912mS H323Evt: v=0 stacknum=250 State, new=NullState, old=NullState id=-1


ACSS - (SME)

 

[amriddle01]

That's dialling 83000 not just 3000

 

[amriddle01]

Oh, no my bad it is stripping the 8 off ....hmmm

 

[amriddle01]

I suspect it isn't seeing the link as being up so it's giving busy tone, can they ping? Are you sure there are no ports being blocked despite what the IT folks say, (there nearly always is)

 

[kewl99]

my feeling is it is a bug some how, the first thing i noticed when creating the H323 line, there is no incoming group id anymore on the voip line tab, not sure when this disappeared?? not sure if it is related, but i've done this many times without any issues, create the ip line, create the shortcode pointing to the ip line group id and normally the call just goes through...

ACSS - (SME)

 

[amriddle01]

The incoming group was useless so they removed it, H323 trunks do not use incoming call route they use shortcodes...that's why

 

[kewl99]

i can ping from ip office to ip office, i can open configs and run system status from both sites..

ACSS - (SME)

 

[amriddle01]

What routers are between the 2 though? Most come with H323 or SIP ALG's and that is what messes with voice ports but leave ping,Manager and SSA etc alone, soincwalls are by far the worse for this

 

[tlpeter]

Didn't find extension by name

Are you sure it is not configured as a SCN
SCN uses names while a H.323 trunk uses extension numbers and not names.


BAZINGA!

I'm not insane, my mother had me tested!

 

[kewl99]

yes, i know, the trunks are not configured as SCN, i do have them set to QSIG, but I have also had them at NONE with the same results...

ACSS - (SME)

 

[tlpeter]

Try setting it to H450.

BAZINGA!

I'm not insane, my mother had me tested!

 

[kewl99]

same thing with H450, says "Number Busy" on screen

ACSS - (SME)