When trying to dial between systems connected via an H450 trunk I continue to get "Unobtainable". I have trunks pointing at each system, short codes sending calls out the group ID, and incoming call routes set up. I have done many of these and never have had these issues I'm experiencing with this system.
When I trace the call on the dialing end using SSA I get:
12/22/14 9:12:12 AM-299ms Extension = 2688, Digit dialed, Digit = 2
12/22/14 9:12:12 AM-326ms Call Ref = 4939, Originator State = Dialling, Type = User, Destination Type = none
12/22/14 9:12:12 AM-794ms Extension = 2688, Digit dialed, Digit = 7
12/22/14 9:12:13 AM-319ms Extension = 2688, Digit dialed, Digit = 0
12/22/14 9:12:13 AM-723ms Extension = 2688, Digit dialed, Digit = 0
12/22/14 9:12:13 AM-726ms Call Ref = 4939, Short Code Matched = System, 27XX
12/22/14 9:12:13 AM-728ms My buttons = 1, Call Ref = 4939, Originator State = Dialling, Type = User, Destination State = Seized, Type = Target List
12/22/14 9:12:13 AM-737ms Line = 23, Channel = 1, Line Ref = 17865, Q.931 Message = Setup, Call Ref = 4939, Direction = From Switch, Calling Party Number = 2688, Called Party Number = 2700
12/22/14 9:12:14 AM-014ms Line = 23, Channel = 1, Q.931 Message = ReleaseComplete, Call Ref = 4939, Direction = To Switch, Cause Code = 34
12/22/14 9:12:14 AM-018ms My buttons = 1, Call Ref = 4939, Originator State = Dialling, Type = User, Destination State = Clearing, Type = Trunk
12/22/14 9:12:14 AM-018ms Call Ref = 4939, Disconnect from Destination End
12/22/14 9:12:14 AM-026ms Extension = 2688, State = Number Unobtainable
When I trace the call on the receiving end using SSA I get:
12/22/14 7:59:00 AM-066ms Line = 20, Line Ref = 32769, Q.931 Message = Setup, Direction = To Switch, Calling Party Number = 2688, Called Party Number = 2700
12/22/14 7:59:00 AM-071ms Call Ref = 22, Originator Type = Trunk, Destination Type = none
12/22/14 7:59:00 AM-072ms Line = 20, Channel Allocated, Channel ID = 1, Call Ref = 22, Line Ref = 32769
12/22/14 7:59:00 AM-084ms Line = 20, Line Ref = 32769, Q.931 Message = ReleaseComplete, Direction = From Switch, Cause Code = 34
When I trace the call on the dialing end with Monitor I get:
10:57:36 410327962mS PRN: 2688: Digit Pressed 2
10:57:36 410327964mS CMCallEvt: 0.19441.0 -1 BaseEP: NEW CMEndpoint f4451aa4 TOTAL NOW=11 CALL_LIST=5
10:57:36 410327964mS CMCallEvt: 0.19441.0 -1 Extn2688.-1: NEW CMExtnEndpoint f4451aa4, Name=Extn2688, Extn=2688, Phys Extn=2688
10:57:36 410327965mS CMCallEvt: CREATE CALL:5423 (f44b61cc)
10:57:36 410327965mS CMCallEvt: 0.19442.0 -1 BaseEP: NEW CMEndpoint f413addc TOTAL NOW=12 CALL_LIST=5
10:57:36 410327967mS CMExtnEvt: Extn2688: CMExtnHandler::SetCurrent( id: 0->19441 )
10:57:36 410327968mS CMExtnRx: v=2688, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[2688] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 12 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Extn2688
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=BST Telecom
10:57:36 410327968mS CMCallEvt: 415.19441.0 5423 Extn2688.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
10:57:36 410327968mS CMExtnEvt: v=83 State, new=Dialling old=Idle,0,0,Extn2688
10:57:36 410327969mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=2688 dir=out complete=0 ses=0
10:57:36 410327969mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:36 410327970mS CMCallEvt: 415.19441.0 5423 Extn2688.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
10:57:36 410327973mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 22/12/14 10:57
10:57:36 410327973mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:36 410327974mS CMExtnTx: v=2688, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Timed: 22/12/14 10:57
10:57:36 410327974mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
10:57:36 410327974mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:36 410327975mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=2 sub= calling=2688 dir=out complete=0 ses=0
10:57:36 410327975mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=2 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:36 410327980mS CD: CALL: 415.19441.0 BState=Idle Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="" [] (0.0) CalledNum=2 () CallingNum=2688 (Extn2688) Internal=1 Time=14 AState=Dialling
10:57:36 410327982mS H323Evt: SetOperational 4000 192.168.40.6:0 to 0
10:57:37 410328356mS PRN: 2688: Digit Pressed 7
10:57:37 410328357mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
10:57:37 410328357mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328358mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=27 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328358mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=27 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328714mS PRN: 2688: Digit Pressed 0
10:57:37 410328715mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
10:57:37 410328715mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328716mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=270 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328716mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=270 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328942mS PRN: 2688: Digit Pressed 0
10:57:37 410328943mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
10:57:37 410328943mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328944mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=2700 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328944mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=2700 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328945mS CMTARGET: 415.19441.0 5423 Extn2688.0: SYS SC: 2700 4 00 sc=type=Dial code=27XX, num=27N callinfop->sending_complete=0 secondary_dialtone=
10:57:37 410328945mS CMARS: FindActiveARSByGroupID GroupID=24 - Not Found
10:57:37 410328945mS CMLRQ: FindActiveLRQByGroupID GroupID=24 - Not Found
10:57:37 410328945mS CMTARGET: Group Id: 24 has NOT been found in Line: 5
10:57:37 410328946mS CMTARGET: Group Id: 24 has NOT been found in Line: 6
10:57:37 410328946mS CMTARGET: Group Id: 24 has NOT been found in Line: 9
10:57:37 410328947mS CMCallEvt: 0.19443.0 -1 BaseEP: NEW CMEndpoint f4446c74 TOTAL NOW=13 CALL_LIST=6
10:57:37 410328950mS CMTARGET: DIAL LINE: 5423 GROUP = 24 SUCCESS = f4446c74
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: CancelTimer CMTCDelayedProcessing
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: INITIAL TARGETING SUCCEEDED
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: GetNoAnswerTimer:15
10:57:37 410328951mS CMCallEvt: 0.19442.0 5423 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
10:57:37 410328952mS CMCallEvt: 0.19443.0 5423 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
10:57:37 410328952mS CMLineTx: v=23
CMSetup
Line: type=IPLine 23 Call: lid=0 id=19443 in=0
Called[2700] Type=Unknown (0) Reason=CMDRdirect Calling[2688] 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 17609
user 'Extn2688' presentation Allowed
IE CMIECallSignalChannelData (8) unknown
Display [Extn2688>2700]
Timed: 22/12/14 10:57
Locale: enu
10:57:37 410328953mS CD: CALL: 415.19441.0 BState=Idle Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="Line 23" [Line 23] (0.0) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=988 AState=Dialling
10:57:37 410328954mS H323Evt: v=0 stacknum=23 State, new=NullState, old=NullState id=-1
10:57:37 410328956mS H323Evt: v=0 stacknum=23 State, new=Initiated, old=NullState id=19443
10:57:38 410329136mS H323Evt: v=0 stacknum=23 State, new=NullState, old=Initiated id=19443
10:57:38 410329137mS CMLineRx: v=23
CMReleaseComp
Line: type=IPLine 23 Call: lid=0 id=19443 in=0
Cause=34, No cct/chan available
10:57:38 410329137mS CMCallEvt: 0.19442.0 5423 TargetingEP: RequestEnd 0.19443.0 5423 H323TrunkEP
10:57:38 410329137mS CMTARGET: 415.19441.0 5423 Extn2688.0: CancelTimer CMTCNoAnswerTimeout
10:57:38 410329138mS CMCallEvt: 0.19442.0 -1 BaseEP: DELETE CMEndpoint f413addc TOTAL NOW=12 CALL_LIST=6
10:57:38 410329140mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 22/12/14 10:57
10:57:38 410329140mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:38 410329140mS CMCallEvt: 0.19443.0 5423 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSCompleted
10:57:38 410329143mS CMLOGGING: CALL:2014/12/2210:57,00:00:00,000,2688,O,2700,2700,Extn2688,,,0,,""n/a,0
10:57:38 410329143mS CD: CALL: 415.19441.0 BState=Disconnecting Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="Line 23" [Line 23] (273.1) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=1178 AState=Dialling
10:57:38 410329143mS CD: CALL: 415.19441.0 Deleted
10:57:38 410329144mS CMExtnEvt: Extn2688: CALL LOST (CMCauseNoChannel)
10:57:38 410329145mS CMExtnEvt: Extn2688: Extn(2688) Calling Party Number(2688) Type(CMNTypeInternal)
10:57:38 410329145mS CMCallEvt: 415.19441.0 -1 Extn2688.0: StateChange: END=X CMCSDialling->CMCSCompletedTone
10:57:38 410329148mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 22/12/14 10:57
10:57:38 410329148mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:38 410329148mS CMExtnEvt: v=83 State, new=CMESCompleted old=Dialling,0,0,Extn2688
10:57:38 410329149mS CMCallEvt: 0.19443.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
10:57:38 410329149mS CMCallEvt: END CALL:5423 (f44b61cc)
10:57:38 410329151mS CMCallEvt: 0.19443.0 -1 BaseEP: DELETE CMEndpoint f4446c74 TOTAL NOW=11 CALL_LIST=5
10:57:38 410329153mS CMMap: PCG::AddToneGenerator g B2[5] for cp[397]b0r1 append pcp[399]b0r1 (total 1)
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::Bind pcp[399]b0r1 to 0.0
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[399]b0r1 Configure 0.0
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[399]b0r1 ConnectIndication 0.0
10:57:38 410329153mS CMMap: a=0.0 b=0.0 pcp[397]b0r1 RTPB2
10:57:38 410329153mS H323Evt: SetOperational 4000 192.168.40.6:49162 to 1
10:57:38 410329300mS H323Evt: Recv: RegistrationRequest 192.168.40.57; Endpoints registered: 53; Endpoints in registration: 0
10:57:39 410330258mS H323Evt: Recv: RegistrationRequest 192.168.40.32; Endpoints registered: 53; Endpoints in registration: 0
10:57:39 410330286mS H323Evt: RTP(50r): 192.168.40.6/49162 192.168.40.62/49332 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=2304 SENT=56 (avg size=164) RECV=50 (avg size=160)
When I trace the call on the receiving end I get:
07:10:48 133558mS CMLineRx: v=20
CMSetup
Line: type=IPLine 20 Call: lid=20 id=1 in=1
Called[2700] Type=Unknown (0) Reason=CMDRdirect Calling[2688] Type=Unknown Plan=Unknown Pres=Allowed (0)
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 17466
user 'Extn2688' presentation Allowed
Display [Extn2688>2700]
07:10:48 133558mS CMCallEvt: 0.1003.0 -1 BaseEP: NEW CMEndpoint f5121ec4 TOTAL NOW=1 CALL_LIST=0
07:10:48 133716mS RES: Mon 22/12/2014 07:10:49 FreeMem=57513100 57319548(2) CachedMem=193552 CMMsg=1(4) Buff=5200 1347 999 7444 5 Links=5661 BTree=14439 CPU=01.51% CPUStats=2/8/3559/15871/458406/0/0 MCR=0 MCW=0
07:10:48 133716mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=49 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=55 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=18(TLS=2) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
07:10:48 133716mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
07:10:48 133731mS PRN: SysSetServiceDateVersion set 7, 1419232248
07:10:48 133731mS PRN: 1 service set date 1419232248 and version 7
07:10:48 133731mS PRN: 22/12/2014 07:10:48
07:10:48 133731mS CMCallEvt: CREATE CALL:1 (f51212dc)
07:10:48 133731mS CMCallEvt: 0.1004.0 -1 BaseEP: NEW CMEndpoint f511fa0c TOTAL NOW=2 CALL_LIST=0
07:10:48 133734mS CD: CALL: 20.1.1 BState=Idle Cut=1 Music=0.0 Aend="Line 20" (270.1) Bend="" [] (0.0) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=175 AState=Idle
07:10:48 133735mS CMCallEvt: 20.1.1 1 H323TrunkEP: StateChange: END=A CMCSIdle->CMCSDialInitiated
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: Setting Hard Timer 4000
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: LOOKUP CALL ROUTE: type=0 called_party=2700 sub= calling=2688 dir=out complete=0 ses=0
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD TARGET (N): number=2700 type=0 depth=1 nobar=1 setorig=1 ses=0
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: SET USER: G Barba orig=1
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD USER: G Barba depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0)
07:10:48 133735mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133736mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133736mS CMTARGET: (null): ADD PRIMARY
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: CancelTimer CMTCDelayedProcessing
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: NO INITIAL TARGETS: G Barba
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD USER: G Barba depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x40) excpt(0x40), allow_redir(1) remote=00000000 simult 0 (0)
07:10:48 133736mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133737mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133737mS CMTARGET: (null): ADD PRIMARY
07:10:48 133737mS CMTARGET: 20.1.1 1 H323TrunkEP: SELECT: TRY VOICEMAIL orig_hg() orig_user(2700)
07:10:48 133737mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD VM TARGET
07:10:48 133737mS CMTARGET: **** 20.1.1 1 H323TrunkEP: MakeVoicemailTarget pbx=<null> local=1 type=3
07:10:48 133737mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133738mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133738mS CMTARGET: (null): ADD PRIMARY
07:10:48 133738mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD VM TARGET: FAILED availability=2
07:10:48 133738mS CMTARGET: 20.1.1 1 H323TrunkEP: Fallback() targeting failed
07:10:48 133739mS CMLOGGING: CALL:2014/12/2207:10,00:00:00,000,2688,I,2700,2700,Extn2688,,,0,,""n/a,0
07:10:48 133739mS CD: CALL: 20.1.1 BState=Idle Cut=0 Music=0.0 Aend="LG Barba(2700)" (270.1) Bend="G Barba(2700)" [] (0.0) CalledNum=2700 (G Barba) CallingNum=2688 (Extn2688) Internal=0 Time=180 AState=Dialling
07:10:48 133739mS CD: CALL: 20.1.1 Deleted
07:10:48 133740mS CMLineTx: v=20
CMReleaseComp
Line: type=IPLine 20 Call: lid=20 id=1 in=1
Cause=34, No cct/chan available
07:10:48 133740mS CMCallEvt: 20.1.1 -1 H323TrunkEP: StateChange: END=X CMCSDialInitiated->CMCSDelete
07:10:48 133740mS CMCallEvt: 0.1004.0 -1 BaseEP: DELETE CMEndpoint f511fa0c TOTAL NOW=1 CALL_LIST=0
07:10:48 133740mS CMCallEvt: END CALL:1 (f51212dc)
07:10:48 133741mS CMTARGET: 20.1.1 -1 BaseEP: ~CMTargetHandler f5119404 ep f5121ec4
07:10:48 133742mS CMCallEvt: 20.1.1 -1 BaseEP: DELETE CMEndpoint f5121ec4 TOTAL NOW=0 CALL_LIST=0
07:10:48 133744mS H323Evt: v=0 stacknum=20 State, new=ReleaseReq, old=Present id=1
07:10:48 133745mS H323Evt: v=0 stacknum=20 State, new=NullState, old=ReleaseReq id=1
When I trace the call on the dialing end using SSA I get:
12/22/14 9:12:12 AM-299ms Extension = 2688, Digit dialed, Digit = 2
12/22/14 9:12:12 AM-326ms Call Ref = 4939, Originator State = Dialling, Type = User, Destination Type = none
12/22/14 9:12:12 AM-794ms Extension = 2688, Digit dialed, Digit = 7
12/22/14 9:12:13 AM-319ms Extension = 2688, Digit dialed, Digit = 0
12/22/14 9:12:13 AM-723ms Extension = 2688, Digit dialed, Digit = 0
12/22/14 9:12:13 AM-726ms Call Ref = 4939, Short Code Matched = System, 27XX
12/22/14 9:12:13 AM-728ms My buttons = 1, Call Ref = 4939, Originator State = Dialling, Type = User, Destination State = Seized, Type = Target List
12/22/14 9:12:13 AM-737ms Line = 23, Channel = 1, Line Ref = 17865, Q.931 Message = Setup, Call Ref = 4939, Direction = From Switch, Calling Party Number = 2688, Called Party Number = 2700
12/22/14 9:12:14 AM-014ms Line = 23, Channel = 1, Q.931 Message = ReleaseComplete, Call Ref = 4939, Direction = To Switch, Cause Code = 34
12/22/14 9:12:14 AM-018ms My buttons = 1, Call Ref = 4939, Originator State = Dialling, Type = User, Destination State = Clearing, Type = Trunk
12/22/14 9:12:14 AM-018ms Call Ref = 4939, Disconnect from Destination End
12/22/14 9:12:14 AM-026ms Extension = 2688, State = Number Unobtainable
When I trace the call on the receiving end using SSA I get:
12/22/14 7:59:00 AM-066ms Line = 20, Line Ref = 32769, Q.931 Message = Setup, Direction = To Switch, Calling Party Number = 2688, Called Party Number = 2700
12/22/14 7:59:00 AM-071ms Call Ref = 22, Originator Type = Trunk, Destination Type = none
12/22/14 7:59:00 AM-072ms Line = 20, Channel Allocated, Channel ID = 1, Call Ref = 22, Line Ref = 32769
12/22/14 7:59:00 AM-084ms Line = 20, Line Ref = 32769, Q.931 Message = ReleaseComplete, Direction = From Switch, Cause Code = 34
When I trace the call on the dialing end with Monitor I get:
10:57:36 410327962mS PRN: 2688: Digit Pressed 2
10:57:36 410327964mS CMCallEvt: 0.19441.0 -1 BaseEP: NEW CMEndpoint f4451aa4 TOTAL NOW=11 CALL_LIST=5
10:57:36 410327964mS CMCallEvt: 0.19441.0 -1 Extn2688.-1: NEW CMExtnEndpoint f4451aa4, Name=Extn2688, Extn=2688, Phys Extn=2688
10:57:36 410327965mS CMCallEvt: CREATE CALL:5423 (f44b61cc)
10:57:36 410327965mS CMCallEvt: 0.19442.0 -1 BaseEP: NEW CMEndpoint f413addc TOTAL NOW=12 CALL_LIST=5
10:57:36 410327967mS CMExtnEvt: Extn2688: CMExtnHandler::SetCurrent( id: 0->19441 )
10:57:36 410327968mS CMExtnRx: v=2688, p1=0
CMSetup
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[2688] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 12 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Extn2688
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=BST Telecom
10:57:36 410327968mS CMCallEvt: 415.19441.0 5423 Extn2688.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
10:57:36 410327968mS CMExtnEvt: v=83 State, new=Dialling old=Idle,0,0,Extn2688
10:57:36 410327969mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=2688 dir=out complete=0 ses=0
10:57:36 410327969mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:36 410327970mS CMCallEvt: 415.19441.0 5423 Extn2688.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
10:57:36 410327973mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
Timed: 22/12/14 10:57
10:57:36 410327973mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:36 410327974mS CMExtnTx: v=2688, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Timed: 22/12/14 10:57
10:57:36 410327974mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[2] Type=Default (100) Reason=CMDRdirect Keypad[2]
10:57:36 410327974mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:36 410327975mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=2 sub= calling=2688 dir=out complete=0 ses=0
10:57:36 410327975mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=2 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:36 410327980mS CD: CALL: 415.19441.0 BState=Idle Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="" [] (0.0) CalledNum=2 () CallingNum=2688 (Extn2688) Internal=1 Time=14 AState=Dialling
10:57:36 410327982mS H323Evt: SetOperational 4000 192.168.40.6:0 to 0
10:57:37 410328356mS PRN: 2688: Digit Pressed 7
10:57:37 410328357mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
10:57:37 410328357mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328358mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=27 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328358mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=27 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328714mS PRN: 2688: Digit Pressed 0
10:57:37 410328715mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
10:57:37 410328715mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328716mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=270 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328716mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=270 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328942mS PRN: 2688: Digit Pressed 0
10:57:37 410328943mS CMExtnRx: v=2688, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
Called[0] Type=Default (100) Reason=CMDRdirect Keypad[0]
10:57:37 410328943mS CMTARGET: 415.19441.0 5423 Extn2688.0: Setting Hard Timer 4000
10:57:37 410328944mS CMTARGET: 415.19441.0 5423 Extn2688.0: LOOKUP CALL ROUTE: type=100 called_party=2700 sub= calling=2688 dir=out complete=0 ses=0
10:57:37 410328944mS CMTARGET: 415.19441.0 5423 Extn2688.0: ADD TARGET (N): number=2700 type=100 depth=1 nobar=1 setorig=1 ses=0
10:57:37 410328945mS CMTARGET: 415.19441.0 5423 Extn2688.0: SYS SC: 2700 4 00 sc=type=Dial code=27XX, num=27N callinfop->sending_complete=0 secondary_dialtone=
10:57:37 410328945mS CMARS: FindActiveARSByGroupID GroupID=24 - Not Found
10:57:37 410328945mS CMLRQ: FindActiveLRQByGroupID GroupID=24 - Not Found
10:57:37 410328945mS CMTARGET: Group Id: 24 has NOT been found in Line: 5
10:57:37 410328946mS CMTARGET: Group Id: 24 has NOT been found in Line: 6
10:57:37 410328946mS CMTARGET: Group Id: 24 has NOT been found in Line: 9
10:57:37 410328947mS CMCallEvt: 0.19443.0 -1 BaseEP: NEW CMEndpoint f4446c74 TOTAL NOW=13 CALL_LIST=6
10:57:37 410328950mS CMTARGET: DIAL LINE: 5423 GROUP = 24 SUCCESS = f4446c74
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: CancelTimer CMTCDelayedProcessing
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: INITIAL TARGETING SUCCEEDED
10:57:37 410328950mS CMTARGET: 415.19441.0 5423 Extn2688.0: GetNoAnswerTimer:15
10:57:37 410328951mS CMCallEvt: 0.19442.0 5423 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
10:57:37 410328952mS CMCallEvt: 0.19443.0 5423 H323TrunkEP: StateChange: END=T CMCSIdle->CMCSOffering
10:57:37 410328952mS CMLineTx: v=23
CMSetup
Line: type=IPLine 23 Call: lid=0 id=19443 in=0
Called[2700] Type=Unknown (0) Reason=CMDRdirect Calling[2688] 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 17609
user 'Extn2688' presentation Allowed
IE CMIECallSignalChannelData (8) unknown
Display [Extn2688>2700]
Timed: 22/12/14 10:57
Locale: enu
10:57:37 410328953mS CD: CALL: 415.19441.0 BState=Idle Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="Line 23" [Line 23] (0.0) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=988 AState=Dialling
10:57:37 410328954mS H323Evt: v=0 stacknum=23 State, new=NullState, old=NullState id=-1
10:57:37 410328956mS H323Evt: v=0 stacknum=23 State, new=Initiated, old=NullState id=19443
10:57:38 410329136mS H323Evt: v=0 stacknum=23 State, new=NullState, old=Initiated id=19443
10:57:38 410329137mS CMLineRx: v=23
CMReleaseComp
Line: type=IPLine 23 Call: lid=0 id=19443 in=0
Cause=34, No cct/chan available
10:57:38 410329137mS CMCallEvt: 0.19442.0 5423 TargetingEP: RequestEnd 0.19443.0 5423 H323TrunkEP
10:57:38 410329137mS CMTARGET: 415.19441.0 5423 Extn2688.0: CancelTimer CMTCNoAnswerTimeout
10:57:38 410329138mS CMCallEvt: 0.19442.0 -1 BaseEP: DELETE CMEndpoint f413addc TOTAL NOW=12 CALL_LIST=6
10:57:38 410329140mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 22/12/14 10:57
10:57:38 410329140mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:38 410329140mS CMCallEvt: 0.19443.0 5423 H323TrunkEP: StateChange: END=B CMCSOffering->CMCSCompleted
10:57:38 410329143mS CMLOGGING: CALL:2014/12/2210:57,00:00:00,000,2688,O,2700,2700,Extn2688,,,0,,""n/a,0
10:57:38 410329143mS CD: CALL: 415.19441.0 BState=Disconnecting Cut=0 Music=0.0 Aend="Extn2688(2688)" (0.0) Bend="Line 23" [Line 23] (273.1) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=1178 AState=Dialling
10:57:38 410329143mS CD: CALL: 415.19441.0 Deleted
10:57:38 410329144mS CMExtnEvt: Extn2688: CALL LOST (CMCauseNoChannel)
10:57:38 410329145mS CMExtnEvt: Extn2688: Extn(2688) Calling Party Number(2688) Type(CMNTypeInternal)
10:57:38 410329145mS CMCallEvt: 415.19441.0 -1 Extn2688.0: StateChange: END=X CMCSDialling->CMCSCompletedTone
10:57:38 410329148mS CMExtnTx: v=2688, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=415 id=19441 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
Timed: 22/12/14 10:57
10:57:38 410329148mS CMExtnTx: v=2688, p1=8164
CMFacility
Line: type=IPLine 250 Call: lid=415 id=83 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
10:57:38 410329148mS CMExtnEvt: v=83 State, new=CMESCompleted old=Dialling,0,0,Extn2688
10:57:38 410329149mS CMCallEvt: 0.19443.0 -1 H323TrunkEP: StateChange: END=X CMCSCompleted->CMCSDelete
10:57:38 410329149mS CMCallEvt: END CALL:5423 (f44b61cc)
10:57:38 410329151mS CMCallEvt: 0.19443.0 -1 BaseEP: DELETE CMEndpoint f4446c74 TOTAL NOW=11 CALL_LIST=5
10:57:38 410329153mS CMMap: PCG::AddToneGenerator g B2[5] for cp[397]b0r1 append pcp[399]b0r1 (total 1)
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::Bind pcp[399]b0r1 to 0.0
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[399]b0r1 Configure 0.0
10:57:38 410329153mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[399]b0r1 ConnectIndication 0.0
10:57:38 410329153mS CMMap: a=0.0 b=0.0 pcp[397]b0r1 RTPB2
10:57:38 410329153mS H323Evt: SetOperational 4000 192.168.40.6:49162 to 1
10:57:38 410329300mS H323Evt: Recv: RegistrationRequest 192.168.40.57; Endpoints registered: 53; Endpoints in registration: 0
10:57:39 410330258mS H323Evt: Recv: RegistrationRequest 192.168.40.32; Endpoints registered: 53; Endpoints in registration: 0
10:57:39 410330286mS H323Evt: RTP(50r): 192.168.40.6/49162 192.168.40.62/49332 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=2304 SENT=56 (avg size=164) RECV=50 (avg size=160)
When I trace the call on the receiving end I get:
07:10:48 133558mS CMLineRx: v=20
CMSetup
Line: type=IPLine 20 Call: lid=20 id=1 in=1
Called[2700] Type=Unknown (0) Reason=CMDRdirect Calling[2688] Type=Unknown Plan=Unknown Pres=Allowed (0)
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 17466
user 'Extn2688' presentation Allowed
Display [Extn2688>2700]
07:10:48 133558mS CMCallEvt: 0.1003.0 -1 BaseEP: NEW CMEndpoint f5121ec4 TOTAL NOW=1 CALL_LIST=0
07:10:48 133716mS RES: Mon 22/12/2014 07:10:49 FreeMem=57513100 57319548(2) CachedMem=193552 CMMsg=1(4) Buff=5200 1347 999 7444 5 Links=5661 BTree=14439 CPU=01.51% CPUStats=2/8/3559/15871/458406/0/0 MCR=0 MCW=0
07:10:48 133716mS RES2: IP 500 V2 9.0.3.0 build 941 Tasks=49 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=55 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=2 SSA=1 TCP=18(TLS=2) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
07:10:48 133716mS RES4: XML MemObjs=61 PoolMem=2097152(1) FreeMem=2081872(1)
07:10:48 133731mS PRN: SysSetServiceDateVersion set 7, 1419232248
07:10:48 133731mS PRN: 1 service set date 1419232248 and version 7
07:10:48 133731mS PRN: 22/12/2014 07:10:48
07:10:48 133731mS CMCallEvt: CREATE CALL:1 (f51212dc)
07:10:48 133731mS CMCallEvt: 0.1004.0 -1 BaseEP: NEW CMEndpoint f511fa0c TOTAL NOW=2 CALL_LIST=0
07:10:48 133734mS CD: CALL: 20.1.1 BState=Idle Cut=1 Music=0.0 Aend="Line 20" (270.1) Bend="" [] (0.0) CalledNum=2700 () CallingNum=2688 (Extn2688) Internal=0 Time=175 AState=Idle
07:10:48 133735mS CMCallEvt: 20.1.1 1 H323TrunkEP: StateChange: END=A CMCSIdle->CMCSDialInitiated
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: Setting Hard Timer 4000
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: LOOKUP CALL ROUTE: type=0 called_party=2700 sub= calling=2688 dir=out complete=0 ses=0
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD TARGET (N): number=2700 type=0 depth=1 nobar=1 setorig=1 ses=0
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: SET USER: G Barba orig=1
07:10:48 133735mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD USER: G Barba depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000 simult 0 (0)
07:10:48 133735mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133736mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133736mS CMTARGET: (null): ADD PRIMARY
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: CancelTimer CMTCDelayedProcessing
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: NO INITIAL TARGETS: G Barba
07:10:48 133736mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD USER: G Barba depth=1 disallow_cw=0 dnd=0 real_call=1 group_call=0 type(CMNTypeUnknown) incl(0x40) excpt(0x40), allow_redir(1) remote=00000000 simult 0 (0)
07:10:48 133736mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133737mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133737mS CMTARGET: (null): ADD PRIMARY
07:10:48 133737mS CMTARGET: 20.1.1 1 H323TrunkEP: SELECT: TRY VOICEMAIL orig_hg() orig_user(2700)
07:10:48 133737mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD VM TARGET
07:10:48 133737mS CMTARGET: **** 20.1.1 1 H323TrunkEP: MakeVoicemailTarget pbx=<null> local=1 type=3
07:10:48 133737mS CMMap: Mapper::AllocateCodec unable to allocate resource
07:10:48 133738mS CMCallEvt: Cannot reserve a codec for Aend, aend is 20.1.1 1 H323TrunkEP
07:10:48 133738mS CMTARGET: (null): ADD PRIMARY
07:10:48 133738mS CMTARGET: 20.1.1 1 H323TrunkEP: ADD VM TARGET: FAILED availability=2
07:10:48 133738mS CMTARGET: 20.1.1 1 H323TrunkEP: Fallback() targeting failed
07:10:48 133739mS CMLOGGING: CALL:2014/12/2207:10,00:00:00,000,2688,I,2700,2700,Extn2688,,,0,,""n/a,0
07:10:48 133739mS CD: CALL: 20.1.1 BState=Idle Cut=0 Music=0.0 Aend="LG Barba(2700)" (270.1) Bend="G Barba(2700)" [] (0.0) CalledNum=2700 (G Barba) CallingNum=2688 (Extn2688) Internal=0 Time=180 AState=Dialling
07:10:48 133739mS CD: CALL: 20.1.1 Deleted
07:10:48 133740mS CMLineTx: v=20
CMReleaseComp
Line: type=IPLine 20 Call: lid=20 id=1 in=1
Cause=34, No cct/chan available
07:10:48 133740mS CMCallEvt: 20.1.1 -1 H323TrunkEP: StateChange: END=X CMCSDialInitiated->CMCSDelete
07:10:48 133740mS CMCallEvt: 0.1004.0 -1 BaseEP: DELETE CMEndpoint f511fa0c TOTAL NOW=1 CALL_LIST=0
07:10:48 133740mS CMCallEvt: END CALL:1 (f51212dc)
07:10:48 133741mS CMTARGET: 20.1.1 -1 BaseEP: ~CMTargetHandler f5119404 ep f5121ec4
07:10:48 133742mS CMCallEvt: 20.1.1 -1 BaseEP: DELETE CMEndpoint f5121ec4 TOTAL NOW=0 CALL_LIST=0
07:10:48 133744mS H323Evt: v=0 stacknum=20 State, new=ReleaseReq, old=Present id=1
07:10:48 133745mS H323Evt: v=0 stacknum=20 State, new=NullState, old=ReleaseReq id=1