One DID of 300 can't call out?

[phonesaz]

I have a client, a shared tenant provider, who has over 300 DID numbers. They use a system called EVO that requires some unusual programming, and each client has their own ARS route to control the DID that is shown.

They recently converted to a fiber circuit with the same carrier. It should have been easy but it wasn't. It is all working now except for one DID that cannot make outbound calls. This is the message I get when the extension attempts a call:

2356317104mS CMARS: FORM: Main - Received Number: 6029995495
2356317104mS CMARS: FOUND A SHORT CODE - short_code: XXXXXXXXXXN - Tel: N - Called_Party: 6029995495 - Line Group Id: 1
2356317104mS CMARS: FindActiveARSByGroupID GroupID=1 - Not Found
2356317104mS CMLRQ: FindActiveLRQByGroupID GroupID=1 - Not Found
2356317105mS CMTARGET: Group Id: 1 has NOT been found in Line: 9
2356317105mS CMTARGET: Group Id: 1 has NOT been found in Line: 10
2356317105mS CMCallEvt: 0.105743.0 -1 BaseEP: NEW CMEndpoint f44535b0 TOTAL NOW=9 CALL_LIST=4
2356317106mS CMTARGET: ISDN BChannel 23: in-service check = 1
2356317106mS CMTARGET: ISDN BChannel 23: in-service check = 1
2356317108mS CMARS: FOUND LINE - Line Id: 5 - using line group id: 1 - Called Number: 6029995495 - Calling Number: 9736
2356317108mS CMARS: SEND Setup TO LINE
2356317108mS CMCallEvt: 0.105743.0 26623 Q931 Trunk:5 CHAN=23: StateChange: END=child CMCSIdle->CMCSOffering
2356317109mS PRN: Setting configured voice gain for ch 23.
2356317109mS CMLineTx: v=5
CMSetup
Line: type=Q931Line 5 Call: lid=0 id=105743 in=0
Called[6029995495] Type=National (2) Reason=CMDRdirect Calling[] Type=National Plan=ISDN
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=23
2356317110mS CD: CALL: 0.105740.0 BState=Idle Cut=2 Music=0.0 Aend="Gabe Buldra(9736)" (13.21) Bend="" [Line 5] (0.0) CalledNum=86029995495 () CallingNum=9736 (Gabe Buldra) Internal=1 Time=3668 AState=Dialling
2356317112mS ISDNL3Evt: v=5 stacknum=5 State, new=Initiated, old=NullState id=105743
2356317123mS ISDNL3Evt: v=5 stacknum=5 State, new=Proceeding, old=Initiated id=105743
2356317124mS CMCallPkt: v=0
CMProceeding
Line: type=Q931Line 5 Call: lid=0 id=105743 in=0
BChan: slot=0 chan=23
2356317124mS CMLineRx: v=5
CMProceeding
Line: type=Q931Line 5 Call: lid=0 id=105743 in=0
BChan: slot=0 chan=23
2356317124mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
2356317124mS CMARS: LINE IS NOW THE B END OF THE CALL - CMARSEndpoint::RequestEnd()
2356317125mS CMARS: CMARSEndpoint::CallLost(cause=124) - Address: 0.105742.0 26623 ARS for Main - Call State: CMCSOverlapRecv
2356317125mS CMCallEvt: 0.105742.0 -1 ARS for Main: StateChange: END=X CMCSOverlapRecv->CMCSDelete
2356317126mS CMCallEvt: 0.105743.0 26623 Q931 Trunk:5 CHAN=23: StateChange: END=B CMCSOffering->CMCSAccept
2356317127mS CMCallEvt: 0.105740.0 26623 Gabe Buldra.0: StateChange: END=A CMCSDialling->CMCSDialled
2356317127mS CMExtnEvt: v=19 State, new=Proceeding old=Dialling,0,0,Gabe Buldra
2356317127mS CMCallEvt: 0.105742.0 -1 BaseEP: DELETE CMEndpoint f450af20 TOTAL NOW=8 CALL_LIST=4
2356317128mS CD: CALL: 0.105740.0 BState=Ringing Cut=3 Music=0.0 Aend="Gabe Buldra(9736)" (13.21) Bend="Line 5" [Line 5] (3.24) CalledNum=6029995495 () CallingNum=9736 (Gabe Buldra) Internal=0 Time=3686 AState=Dialled
2356317130mS CMMap: PCG::MapBChan pcp[305]b1r0 cp_b f4ed5388 other_cp_b 0 type CGTypeSimple
2356317130mS CMMap: PCG::MapBChan pcp[94]b1r0 cp_b f50f8050 other_cp_b f4ed5388 type CGTypeSimple
2356317130mS CMMap: a=13.21 b=3.24 M12
2356317382mS ISDNL3Evt: v=5 stacknum=5 State, new=ReleaseReq, old=Proceeding id=105743
2356317388mS ISDNL3Evt: v=5 stacknum=5 State, new=NullState, old=ReleaseReq id=105743
2356317389mS CMCallPkt: v=0
CMReleaseComp
Line: type=Q931Line 5 Call: lid=0 id=105743 in=0
BChan: slot=0 chan=23
Cause=41, Temporary failure
2356317389mS CMLineRx: v=5
CMReleaseComp
Line: type=Q931Line 5 Call: lid=0 id=105743 in=0
BChan: slot=0 chan=23
Cause=41, Temporary failure
2356317389mS CMCallEvt: 0.105743.0 26623 Q931 Trunk:5 CHAN=23: StateChange: END=B CMCSAccept->CMCSCompleted
2356317391mS CMLOGGING: CALL:2017/06/2715:45,00:00:00,000,9736,O,6029995495,86029995495,GabeBuldra,,,0,,""n/a,0
2356317392mS CD: CALL: 0.105740.0 BState=Disconnecting Cut=1 Music=0.0 Aend="Gabe Buldra(9736)" (13.21) Bend="Line 5" [Line 5] (3.24) CalledNum=6029995495 () CallingNum=9736 (Gabe Buldra) Internal=0 Time=3950 AState=Dialled
2356317392mS CD: CALL: 0.105740.0 Deleted
2356317393mS CMExtnEvt: Gabe Buldra: CALL LOST (CMCauseTemporaryFailure)
2356317393mS CMExtnEvt: Gabe Buldra: Extn(9736) Calling Party Number(9736) Type(CMNTypeInternal)
2356317394mS CMCallEvt: 0.105740.0 -1 Gabe Buldra.0: StateChange: END=X CMCSDialled->CMCSCompletedTone
2356317394mS CMExtnEvt: v=19 State, new=CMESCompleted old=Proceeding,0,0,Gabe Buldra
2356317395mS CMCallEvt: 0.105743.0 -1 Q931 Trunk:5 CHAN=23: StateChange: END=X CMCSCompleted->CMCSDelete
2356317395mS CMCallEvt: END CALL:26623 (f432b8f0)
2356317396mS CMTARGET: ISDN BChannel 23: in-service check = 1
2356317396mS CMTARGET: ISDN BChannel 23: in-service check = 1
2356317397mS CMCallEvt: 0.105743.0 -1 BaseEP: DELETE CMEndpoint f44535b0 TOTAL NOW=7 CALL_LIST=3
2356317398mS CMMap: PCG::UnmapBChan pcp[305]b1r0 cp_b f4ed5388 other_cp_b f50f8050
2356317398mS CMMap: a=3.24 b=13.21 M02
2356317398mS CMMap: PCG::UnmapBChan pcp[94]b1r0 cp_b f50f8050 other_cp_b 0
2356317399mS CMMap: a=21.8 b=0.0 DTMF::AllocateRAS allocated CMRTTonegen resource busy 7, total 8
2356317399mS CMMap: a=21.8 b=1.255 T
2356317399mS CMMap: a=21.8 b=13.21 M22
2356317650mS RES: Tue 27/6/2017 15:45:28 FreeMem=45288452 44002556(1) CachedMem=1285896 CMMsg=6(7) Buff=5200 1388 1000 12343 5 Links=893016 BTree=0 CPU=8/15/221/10043/981385/1
2356317650mS RES2: (SE-E) IP 500 V2 8.1(73) Tasks=52 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=88 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=3 SSA=1 TCP=20 TAPI=3 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
2356317650mS RES4: XML MemObjs=45 PoolMem=2097152(1) FreeMem=2082064(1)
2356318567mS CMCallEvt: 0.105740.0 -1 Gabe Buldra.0: StateChange: END=X CMCSCompletedTone->CMCSCompleted
2356318567mS CMExtnEvt: v=19 State, new=PortRecoverDelay old=CMESCompleted,0,0,Gabe Buldra
2356318568mS CMExtnEvt: Gabe Buldra: CALL LOST (CMCauseForceClear)
2356318568mS CMExtnEvt: Gabe Buldra: Extn(9736) Calling Party Number(9736) Type(CMNTypeInternal)
2356318568mS CMExtnEvt: Gabe Buldra: CMExtnHandler::SetCurrent( id: 105740->0 )
2356318569mS CMCallEvt: 0.105740.0 -1 Gabe Buldra.-1: StateChange: END=X CMCSCompleted->CMCSDelete
2356318569mS CMTARGET: 0.105740.0 -1 BaseEP: ~CMTargetHandler f438c588 ep f435b758
2356318569mS CMCallEvt: 0.105740.0 -1 BaseEP: DELETE CMEndpoint f435b758 TOTAL NOW=6 CALL_LIST=3
2356318572mS CMMap: a=21.8 b=13.21 M02
2356318572mS CMMap: a=21.8 b=0.0 T0
2356318572mS CMMap: a=21.8 b=0.0 DTMF::~DTMF freed CMRTTonegen resource busy 6, total 8
2356319617mS CMCallEvt: 0.105744.0 -1 BaseEP: NEW CMEndpoint f435b758 TOTAL NOW=7 CALL_LIST=3
2356319617mS CMCallEvt: 0.105744.0 -1 Gabe Buldra.-1: NEW CMExtnEndpoint f435b758, Name=Gabe Buldra, Extn=9736, Phys Extn=9736
2356319618mS CMCallEvt: CREATE CALL:26624 (f432b8f0)
2356319618mS CMCallEvt: 0.105745.0 -1 BaseEP: NEW CMEndpoint f438eb50 TOTAL NOW=8 CALL_LIST=3
2356319620mS CMExtnEvt: Gabe Buldra: CMExtnHandler::SetCurrent( id: 0->105744 )
2356319621mS CMExtnEvt: v=19 State, new=Idle old=PortRecoverDelay,0,0,Gabe Buldra
2356319622mS CMCallEvt: 0.105744.0 26624 Gabe Buldra.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
2356319622mS CMExtnEvt: v=19 State, new=Dialling old=Idle,0,0,Gabe Buldra
2356319622mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: LOOKUP CALL ROUTE: type=100 called_party= sub= calling=9736 dir=out complete=0 ses=0
2356319622mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
2356319623mS CMCallEvt: 0.105744.0 26624 Gabe Buldra.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
2356319625mS CD: CALL: 0.105744.0 BState=Idle Cut=1 Music=3.0 Aend="Gabe Buldra(9736)" (13.21) Bend="" [] (0.0) CalledNum= () CallingNum=9736 (Gabe Buldra) Internal=1 Time=7 AState=DialInitiated
2356319630mS CMMap: a=13.21 b=0.0 D1
2356320380mS PRN: 9736: Digit Pressed 8
2356320382mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: Setting Hard Timer 4000
2356320382mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: LOOKUP CALL ROUTE: type=100 called_party=8 sub= calling=9736 dir=out complete=0 ses=0
2356320382mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: ADD TARGET (N): number=8 type=100 depth=1 nobar=1 setorig=1 ses=0
2356320383mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: USER SC: 8 1 sc=type=Dial code=8, num=N
2356320383mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
2356320383mS CMARS: MakeCallTarget - Called Number:
2356320383mS CMCallEvt: 0.105746.0 -1 BaseEP: NEW CMEndpoint f450af20 TOTAL NOW=9 CALL_LIST=4
2356320384mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: CancelTimer CMTCDelayedProcessing
2356320384mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: INITIAL TARGETING SUCCEEDED
2356320385mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: GetNoAnswerTimer:30
2356320386mS CMCallEvt: 0.105745.0 26624 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
2356320386mS CMCallEvt: 0.105746.0 26624 ARS for Main: StateChange: END=T CMCSIdle->CMCSOffering
2356320387mS CMCallEvt: 0.105745.0 26624 TargetingEP: RequestEnd 0.105746.0 26624 ARS for Main
2356320387mS CMTARGET: 0.105744.0 26624 Gabe Buldra.0: CancelTimer CMTCNoAnswerTimeout
2356320388mS CMCallEvt: 0.105746.0 26624 ARS for Main: StateChange: END=B CMCSOffering->CMCSOverlapRecv
2356320389mS CMARS: FORM: Main - Received Number:
2356320389mS CMARS: CMARSTargetingPending
2356320389mS CMCallEvt: 0.105745.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
2356320389mS CMCallEvt: 0.105745.0 -1 BaseEP: DELETE CMEndpoint f438eb50 TOTAL NOW=8 CALL_LIST=4

Oddly enough other ARS patterns work, they just show the wrong DID number. If I take the exact working ARS and copy it, change the DID number, and use it, it stops working. I am not sure what to trouble shoot next; any advise appreciated.

 

[TouchToneTommy]

I see "CallingNum=9736" which is the extension number, not the 10 digit DID number associated with his extension.

 

[amriddle01]

Plus you seem to be targetting dead lines before it gets to the correcr line, I'd look at that also

 

[phonesaz]

They all show calling number =xxxx where xxxx is the last four-digits of the 10 digit number. And calling group 1 has 3 full PRI's and is the only group on the system. I don't understand this entry, specifically the reference to line:9 and line:10?

2356317105mS CMTARGET: Group Id: 1 has NOT been found in Line: 9
2356317105mS CMTARGET: Group Id: 1 has NOT been found in Line: 10

Then it jumps to this, which it seems to like as a 'working' line?

CMARS: FOUND LINE - Line Id: 5 - using line group id: 1 - Called Number: 6029995495 - Calling Number: 9736

This company has been using using the same setup for about 4 years; whenever they add a new tenant they just copy and paste from an ARS table that works, and change the 'show instead' number to an available DID. The reason we do it this way is because the carrier can't or wont show individual DID numbers on outbound calls so this was our work around.

 

[TouchToneTommy]

Do your trace with ALL of the boxes checked on the ISDN tab, let's see a failed call. And do you see anything in SSA with Trace On while calling? It is easier to find the cause code in SSA trace, but all the info is in Monitor