Issues with PRI dialing out - Please help !!

[Flatts]

I have 2 PRIs going to an IP Office 9.1.2 (Expansion on a Server Edition). Each PRI is a seperate daughter card. I am having issues dialing out. The sets I am testing from are 9508s connected to the IPO 500v2, so I am focusing on the short code and ARS there. I am getting the same results from IP sets connected to the Primary, so I don't believe that is the issue.

What is happening is, when I make an outgoing call, the call drops, and the PRI resets. After the reset, and I don't drop the call, it keeps trying different channels, and randomly locking them out. I have spoken to the provider several times, and they say of course, no problem at their end.

I am running on DMS100. I have tried NI-2. My outgoing short code is currently 9N; / Dial / N / ARS 50. ARS 50 is ? / Dial / . / Line Group 77.

When I have my outgoing short code as 9N; / Dial / N / Line Group 77, I get disconnected from the destination end.

I have tried using NSXXXXXXXXX, and having a DID on the users system outgoing. No change.

My PRIs are set as Line Group 7 for incoming, 77 for outgoing.

This is a new install, cutting over Thursday.

Any assistance at all would be amazing. I'll reply to this post with a trace.

Avaya/Norstar/BCM/Cisco Telephone System Tech

 

[Flatts]

*** Please note that I have X'd out my testing number ****




1182865mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: Setting Hard Timer 4000
1182865mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=91416XXXXXXX sub= calling=1259 dir=out complete=0 ses=0
1182865mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: ADD TARGET (N): number=91416XXXXXXX type=100 depth=1 nobar=1 setorig=1 ses=0
1186864mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: TimerExpired cause=CMTCDelayedProcessing
1186864mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=91416XXXXXXX sub= calling=1259 dir=out complete=1 ses=0
1186864mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: ADD TARGET (N): number=91416XXXXXXX type=100 depth=1 nobar=1 setorig=1 ses=0
1186865mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: SYS SC: 91416XXXXXXX 3 1416XXXXXX sc=type=Dial code=9N;, num=Ns5198842310 callinfop->sending_complete=1 secondary_dialtone=
1186865mS CMARS: FindActiveARSByGroupID GroupID=77 - Not Found
1186866mS CMCallEvt: 0000000000000000 0.1049.0 -1 BaseEP: NEW CMEndpoint f17aec78 TOTAL NOW=3 CALL_LIST=1
1186866mS CMTARGET: ISDN BChannel 7: in-service check = 1
1186867mS CMTARGET: ISDN BChannel 7: in-service check = 1
1186868mS CMTARGET: DIAL LINE: 11 GROUP = 77 SUCCESS = f17aec78
1186868mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: INITIAL TARGETING SUCCEEDED
1186869mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: GetNoAnswerTimer:15
1186869mS CMCallEvt: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: StateChange: END=A CMCSDialling->CMCSDialled
1186869mS CMExtnEvt: v=8 State, new=Proceeding old=Dialling,0,0,KW CompRm Bnch
1186869mS CMCallEvt: 0000000000000000 0.1048.0 11 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
1186870mS CMCallEvt: 0a0064de00000419 0.1049.0 11 Q931 Trunk:9 CHAN=7: StateChange: END=T CMCSIdle->CMCSOffering
1186870mS T1DSP: PRIU DSP 3: channel 7 (timeslot 14), restore gains tx 10, rx 10
1186871mS CD: CALL: 0.1047.0 BState=Idle Cut=1 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="Line 9" [Line 9] (0.0) CalledNum=91416XXXXXXX () CallingNum=1259 (KW CompRm Bnch) Internal=0 Time=7234 AState=Dialled
1186871mS CD2: CALL:S 0.1047.0,0.1048.0,8,0,1,0,0,0,KW CompRm Bnch(1259),,Line 9,8.10,0.0,100.100,91416XXXXXXX,100.101,1259,,,100,91416XXXXXXX,100,,0,16,0,1,0.0,,,,,,,0,7234,0,0,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
1186872mS ISDNL3Evt: v=9 stacknum=9 State, new=Initiated, old=NullState id=1049
1194872mS ISDNL3Evt: v=9 stacknum=9 State, new=NullState, old=Initiated id=1049
1194873mS CMCallEvt: 0000000000000000 0.1048.0 11 TargetingEP: RequestEnd 0a0064de00000419 0.1049.0 11 Q931 Trunk:9 CHAN=7
1194873mS CMTARGET: 0a0064de00000417 0.1047.0 11 KW CompRm Bnch.0: CancelTimer CMTCNoAnswerTimeout
1194873mS CMCallEvt: 0000000000000000 0.1048.0 -1 BaseEP: DELETE CMEndpoint f17c0e10 TOTAL NOW=2 CALL_LIST=1
1194874mS CMCallEvt: 0a0064de00000419 0.1049.0 11 Q931 Trunk:9 CHAN=7: StateChange: END=B CMCSOffering->CMCSCompleted
1194875mS CMLOGGING: CALL:2015/11/0317:34,00:00:00,000,1259,O,1416XXXXXXXX,91416XXXXXXX,KWCompRmBnch,,,0,,"",0,n/a
1194875mS CD: CALL: 0.1047.0 BState=Disconnecting Cut=1 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="Line 9" [Line 9] (5.8) CalledNum=1416XXXXXXX () CallingNum=1259 (KW CompRm Bnch) Internal=0 Time=15238 AState=Dialled
1194875mS CD2: CALL:S 0.1047.0,0.1048.0,8,3,1,0,0,0,KW CompRm Bnch(1259),Line 9,,8.10,5.8,100.100,1416XXXXXXX,100.101,1259,,,100,91416XXXXXXX,100,,0,16,0,1,0.0,,,,,,,0,15238,0,0,0,0,enu,,0,,0,0,0,0,,11,,,,,,,,,,,,,,,,0,0,KW CompRm Bnch,0,,3,0,0,0,0,0,0
,1,618,100
1194875mS CD: CALL: 0.1047.0 Deleted
1194876mS CMExtnEvt: KW CompRm Bnch: CALL LOST (CMCauseNormal)
1194876mS CMExtnEvt: KW CompRm Bnch: Extn(1259) Calling Party Number(1259) Type(CMNTypeInternal)
1194877mS CMCallEvt: 0a0064de00000417 0.1047.0 -1 KW CompRm Bnch.0: StateChange: END=X CMCSDialled->CMCSCompleted
1194877mS CMExtnEvt: v=8 State, new=PortRecoverDelay old=Proceeding,0,0,KW CompRm Bnch
1194878mS CMExtnEvt: KW CompRm Bnch: CMExtnHandler::SetCurrent( id: 1047->0 )
1194878mS CMCallEvt: 0a0064de00000417 0.1047.0 -1 KW CompRm Bnch.-1: StateChange: END=X CMCSCompleted->CMCSDelete
1194879mS CMTARGET: 0a0064de00000417 0.1047.0 -1 BaseEP: ~CMTargetHandler f17bb178 ep f17c2d80
1194879mS CMCallEvt: 0a0064de00000417 0.1047.0 -1 BaseEP: DELETE CMEndpoint f17c2d80 TOTAL NOW=1 CALL_LIST=0
1194879mS CMCallEvt: 0a0064de00000419 0.1049.0 -1 Q931 Trunk:9 CHAN=7: StateChange: END=X CMCSCompleted->CMCSDelete
1194879mS CMCallEvt: END CALL:11 (f17c2864)
1194880mS CMTARGET: ISDN BChannel 7: in-service check = 1
1194880mS CMTARGET: ISDN BChannel 7: in-service check = 1
1194880mS CD2: CALL 0.1047.0,0.1048.0,11,,,,,,,,,,,,,,,,0,0,KW CompRm Bnch,0,,3,0,0,0,0,0,0,1,618,100
1194880mS CMCallEvt: 0a0064de00000419 0.1049.0 -1 BaseEP: DELETE CMEndpoint f17aec78 TOTAL NOW=0 CALL_LIST=0
1196878mS CMExtnEvt: KW CompRm Bnch: Recover Timer reason=CMTRWrapUp
1196878mS CMExtnEvt: v=8 State, new=Idle old=PortRecoverDelay,0,0,KW CompRm Bnch
1204694mS T1DSP: PRIU DSP 2: is alive

********** SysMonitor v9.1.2.0 build 91 [connected to 10.0.100.222 (KrausSEIPOExp (Server Edition(E)))] **********
1205976mS T1DSP: PRIU DSP 3: is alive


Avaya/Norstar/BCM/Cisco Telephone System Tech

 

[Flatts]

** Here is a trace of what happens when I set my outgoing short code to 9N; / Dial / N / 50: Main **

2018598mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1259: Digit Key Pressed 5
2018599mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: Setting Hard Timer 4000
2018599mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=918006655775 sub= calling=1259 dir=out complete=0 ses=0
2018599mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: ADD TARGET (N): number=918006655775 type=100 depth=1 nobar=1 setorig=1 ses=0
2022598mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: TimerExpired cause=CMTCDelayedProcessing
2022598mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=918006655775 sub= calling=1259 dir=out complete=1 ses=0
2022598mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: ADD TARGET (N): number=918006655775 type=100 depth=1 nobar=1 setorig=1 ses=0
2022599mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: SYS SC: 918006655775 3 18006655775 sc=type=Dial code=9N;, num=N callinfop->sending_complete=1 secondary_dialtone=
2022599mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
2022599mS CMARS: MakeCallTarget - Called Number: 18006655775
2022600mS CMCallEvt: 0000000000000000 0.1052.0 -1 BaseEP: NEW CMEndpoint f17b7d88 TOTAL NOW=3 CALL_LIST=1
2022601mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: INITIAL TARGETING SUCCEEDED
2022601mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: GetNoAnswerTimer:15
2022601mS CMCallEvt: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: StateChange: END=A CMCSDialling->CMCSDialled
2022601mS CMExtnEvt: v=8 State, new=Proceeding old=Dialling,0,0,KW CompRm Bnch
2022602mS CMCallEvt: 0000000000000000 0.1051.0 12 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
2022602mS CMCallEvt: 0000000000000000 0.1052.0 12 ARS for Main: StateChange: END=T CMCSIdle->CMCSOffering
2022603mS CMCallEvt: 0000000000000000 0.1051.0 12 TargetingEP: RequestEnd 0000000000000000 0.1052.0 12 ARS for Main
2022603mS CMTARGET: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: CancelTimer CMTCNoAnswerTimeout
2022604mS CMCallEvt: 0000000000000000 0.1052.0 12 ARS for Main: StateChange: END=B CMCSOffering->CMCSOverlapRecv
2022604mS CMARS: FORM: Main - Received Number: 18006655775
2022604mS CMARS: FOUND A SHORT CODE - short_code: ? - Tel: . - Called_Party: 18006655775 - Line Group Id: 77
2022604mS CMARS: SetCurrentTarget: Short_Code: ? - Line_Group_ID: 77
2022604mS CMARS: FindActiveARSByGroupID GroupID=77 - Not Found
2022605mS CMCallEvt: 0000000000000000 0.1053.0 -1 BaseEP: NEW CMEndpoint f17aec78 TOTAL NOW=4 CALL_LIST=1
2022605mS CMTARGET: ISDN BChannel 23: in-service check = 1
2022605mS CMTARGET: ISDN BChannel 23: in-service check = 1
2022607mS CMARS: ModifyCMARSTarget: Short_Code: ? - Line_Group_ID: 77 set line status to CMARS_TRYING
2022607mS CMARS: FOUND LINE - Line Id: 5 - using line group id: 77 (code ?, line 77) - Called Number: 18006655775 - Calling Number: 1259
2022607mS CMARS: SEND Setup TO LINE
2022607mS CMCallEvt: 0a0064de0000041d 0.1053.0 12 Q931 Trunk:5 CHAN=23: StateChange: END=child CMCSIdle->CMCSOffering
2022608mS T1DSP: PRIU DSP 2: channel 23 (timeslot 46), restore gains tx 10, rx 10
2022608mS CMCallEvt: 0000000000000000 0.1051.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
2022608mS CMCallEvt: 0000000000000000 0.1051.0 -1 BaseEP: DELETE CMEndpoint f17c0e10 TOTAL NOW=3 CALL_LIST=1
2022608mS CD: CALL: 0.1050.0 BState=Idle Cut=3 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [Line 5] (0.0) CalledNum=918006655775 () CallingNum=1259 (KW CompRm Bnch) Internal=1 Time=7201 AState=Dialled
2022608mS CD2: CALL:S 0.1050.0,0.1051.0,8,0,1,0,1,0,KW CompRm Bnch(1259),,Line 5,8.10,0.0,100.100,918006655775,100.101,1259,,,100,918006655775,100,,0,16,0,1,0.0,,,,,,,1,7201,0,0,0,0,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
2022611mS ISDNL3Evt: v=5 stacknum=5 State, new=Initiated, old=NullState id=1053
2030611mS ISDNL3Evt: v=5 stacknum=5 State, new=NullState, old=Initiated id=1053
2030612mS CMARS: LINE ep Received: CMReleaseComp - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
2030612mS CMCallEvt: 0a0064de0000041d 0.1053.0 -1 Q931 Trunk:5 CHAN=23: StateChange: END=X CMCSOffering->CMCSCompleted
2030613mS CMARS: ModifyCMARSTarget: Short_Code: ? - Line_Group_ID: 77 set line status to CMARS_OUTOFSERVICE
2030613mS CMARS: Target: Short_Code: ? - Line_Group_ID: 77 has been set to: CMARS_OUTOFSERVICE
2030613mS CMCallEvt: 0a0064de0000041a 0.1052.0 12 ARS for Main: StateChange: END=B CMCSOverlapRecv->CMCSAccept
2030613mS CMCallEvt: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: StateChange: END=A CMCSDialled->CMCSRingBack
2030614mS CMExtnEvt: v=8 State, new=Alerting old=Proceeding,0,0,KW CompRm Bnch
2030615mS CD: CALL: 0.1050.0 BState=Ringing Cut=3 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [] (0.0) CalledNum=918006655775 () CallingNum=1259 (KW CompRm Bnch) Internal=1 Time=15208 AState=Ringing
2030615mS CD2: CALL:S 0.1050.0,0.1051.0,1,1,1,0,1,0,KW CompRm Bnch(1259),,,8.10,0.0,100.100,918006655775,100.101,1259,,,100,918006655775,100,,0,16,0,1,0.0,,,,,,,1,15208,0,0,0,0,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
2030618mS CMCallEvt: 0a0064de0000041d 0.1053.0 -1 Q931 Trunk:5 CHAN=23: StateChange: END=X CMCSCompleted->CMCSDelete
2030618mS CMTARGET: ISDN BChannel 23: in-service check = 1
2030619mS CMTARGET: ISDN BChannel 23: in-service check = 1
2030619mS CMCallEvt: 0a0064de0000041d 0.1053.0 -1 BaseEP: DELETE CMEndpoint f17aec78 TOTAL NOW=2 CALL_LIST=1
2031613mS CMARS: Retarget existing BUSY targets - Num of Busy Targets: 1 - Current Form: Main
2032713mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1259: Menu Key Pressed 12:I
2032714mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1259: Feature Key Pressed 6CPLFeatureDrop
2032715mS CMCallEvt: 0a0064de0000041a 0.1050.0 12 KW CompRm Bnch.0: StateChange: END=A CMCSRingBack->CMCSCompleted
2032715mS CMExtnEvt: v=8 State, new=PortRecoverDelay old=Alerting,0,0,KW CompRm Bnch
2032716mS CMLOGGING: CALL:2015/11/0317:48,00:00:00,000,1259,O,918006655775,918006655775,KWCompRmBnch,,,1,,"",0,n/a
2032716mS CD: CALL: 0.1050.0 BState=Ringing Cut=2 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [] (0.0) CalledNum=918006655775 () CallingNum=1259 (KW CompRm Bnch) Internal=1 Time=17309 AState=Idle
2032717mS CD2: CALL:S 0.1050.0,0.1051.0,0,1,0,0,1,0,KW CompRm Bnch(1259),,,8.10,0.0,100.100,918006655775,100.101,1259,,,100,918006655775,100,,0,16,0,1,0.0,,,,,,,1,17309,0,0,0,0,enu,,0,,0,0,0,0,,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
2032717mS CD: CALL: 0.1050.0 Deleted
2032717mS CD2: CALL 0.1050.0,0.1051.0,12,,,,,,,,,,,,,,,,,,,,,,,,,,,,,,
2032717mS CMExtnEvt: KW CompRm Bnch: CALL LOST (CMCauseNormal)
2032717mS CMExtnEvt: KW CompRm Bnch: Extn(1259) Calling Party Number(1259) Type(CMNTypeInternal)
2032717mS CMExtnEvt: KW CompRm Bnch: CMExtnHandler::SetCurrent( id: 1050->0 )
2032718mS CMCallEvt: 0a0064de0000041a 0.1050.0 -1 KW CompRm Bnch.-1: StateChange: END=X CMCSCompleted->CMCSDelete
2032718mS CMARS: CMARSEndpoint::CallLost(cause=16) - Address: 0a0064de0000041a 0.1052.0 12 ARS for Main - Call State: CMCSAccept
2032719mS CMCallEvt: 0a0064de0000041a 0.1052.0 -1 ARS for Main: StateChange: END=X CMCSAccept->CMCSDelete
2032719mS CMCallEvt: 0a0064de0000041a 0.1052.0 -1 BaseEP: DELETE CMEndpoint f17b7d88 TOTAL NOW=1 CALL_LIST=0
2032719mS CMCallEvt: END CALL:12 (f17c2864)
2032720mS CMTARGET: 0a0064de0000041a 0.1050.0 -1 BaseEP: ~CMTargetHandler f17bb178 ep f17c2d80
2032720mS CMCallEvt: 0a0064de0000041a 0.1050.0 -1 BaseEP: DELETE CMEndpoint f17c2d80 TOTAL NOW=0 CALL_LIST=0
2034718mS CMExtnEvt: KW CompRm Bnch: Recover Timer reason=CMTRWrapUp
2034718mS CMExtnEvt: v=8 State, new=Idle old=PortRecoverDelay,0,0,KW CompRm Bnch
2044694mS T1DSP: PRIU DSP 2: is alive
2045976mS T1DSP: PRIU DSP 3: is alive

Avaya/Norstar/BCM/Cisco Telephone System Tech

 

[holdmusic34]

CallLost(cause=16
The cause code 16 is a normal hang up.


Cause code 11 shows excessive digits received in the manual.

At this juncture, I would check my dial delay count and dial delay timers. Push them out a bit.
Also please try enbloc ON dialling in Features> Call Settings.

Best. Commercial. Ever.

 

[Flatts]

Thanks for the suggestion, but having the same issue.

Referred it to Bell. I am sure I know what their response will be .....

Avaya/Norstar/BCM/Cisco Telephone System Tech

 

[mforrence]

I'd change Monitor to show only the ISDN Layer 3 events, plus the basics on system tab. It would make it easier to see both sides of the call setup

 

[Flatts]

Heres a new trace. I have 1 PRI in loopback as I am testing with Bell :

11:49:35 3581368mS PRN: LAW=U PRI=2, BRI=0, ALOG=4, VCOMP=74, MDM=0, WAN=0, MODU=6 LANM=0 CkSRC=9 VMAIL=1(VER=3 TYP=2) 1-X=1 CALLS=1(TOT=6)
11:49:35 3581913mS ISDNL3Evt: v=5 p1=5,p2=1001,p3=5,p4=0,s1=
11:49:36 3582949mS ISDNL3Tx: v=9 peb=9
ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=0004(Remote)
Message Type = Setup
InformationElement = BearerCapability
0000 04 03 90 90 a2 .....
InformationElement = CHI
0000 18 03 a9 83 88 .....
InformationElement = CallingPartyNumber
0000 6c 0c 21 a0 35 31 39 38 38 34 32 33 31 30 l.!.5198842310
InformationElement = CalledPartyNumber
0000 70 0c 80 31 34 31 36 39 36 37 31 31 31 31 p..14169671111
InformationElement = Sending Complete
11:49:40 3586949mS ISDNL3Evt: v=9 stacknum=9 State, new=NullState, old=Initiated id=1025
11:49:40 3586949mS ISDNL3Tx: v=9 peb=9
ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=0004(Remote)
Message Type = ReleaseComplete
InformationElement = CAUSE
0000 08 02 80 9f ....
11:49:40 3586950mS CMLineRx: v=9
CMReleaseComp
Line: type=Q931Line 9 Call: lid=0 id=1025 in=0
BChan: slot=0 chan=8
11:49:40 3586950mS CMARS: LINE ep Received: CMReleaseComp - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
11:49:40 3586951mS CMLineTx: v=9
CMDisconnect
Line: type=Q931Line 9 Call: lid=0 id=1025 in=0
Cause=16, Normal call clearing
11:49:40 3586951mS CMCallEvt: 0a0064de00000401 0.1025.0 -1 Q931 Trunk:9 CHAN=8: StateChange: END=X CMCSOffering->CMCSCompleted
11:49:40 3586951mS CMARS: ModifyCMARSTarget: Short_Code: N; - Line_Group_ID: 77 set line status to CMARS_OUTOFSERVICE
11:49:40 3586951mS CMARS: Target: Short_Code: N; - Line_Group_ID: 77 has been set to: CMARS_OUTOFSERVICE
11:49:40 3586951mS CMCallEvt: 0a0064de000003fe 0.1024.0 6 ARS for Main: StateChange: END=B CMCSOverlapRecv->CMCSAccept
11:49:40 3586952mS CMCallEvt: 0a0064de000003fe 0.1022.0 6 KW CompRm Bnch.0: StateChange: END=A CMCSDialling->CMCSRingBack
11:49:40 3586952mS CMExtnEvt: v=8 State, new=Alerting old=Dialling,0,0,KW CompRm Bnch
11:49:40 3586953mS CMExtnTx: v=1259, p1=0
CMProgress
Line: type=DigitalExtn 6 Call: lid=0 id=1022 in=0
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLUser (0), pd=CMPDInbandPattern (8)
Display [WAITING_FOR_LINE]
Timed: 04/11/15 11:49
11:49:40 3586953mS CD: CALL: 0.1022.0 BState=Ringing Cut=3 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [] (0.0) CalledNum=914169671111 () CallingNum=1259 (WITHHELD) Internal=1 Time=18519 AState=Ringing
11:49:40 3586955mS CMMap: a=21.42 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail(f52e6100) resource busy 1, total 45
11:49:40 3586955mS CMMap: a=21.42 b=1.65535 T
11:49:40 3586956mS CMMap: PCG::MapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8 type CGTypeDTMF
11:49:40 3586956mS CMMap: a=21.42 b=8.10 M22
11:49:40 3586956mS CMMap: DTMF:layTones g T[27] ,EEEEE
11:49:40 3586956mS CMMap: Started playing tones, cp[312]b1r0 (from g null)
11:49:40 3586956mS CMMap: cp[312]b1r0 SetOperGroup from g null to g null not executed, playing tones in progress ,EEEEE
11:49:40 3586957mS CMLineRx: v=9
CMReleaseComp
Line: type=Q931Line 9 Call: lid=0 id=1025 in=0
Cause=16, Normal call clearing
11:49:40 3586957mS CMCallEvt: 0a0064de00000401 0.1025.0 -1 Q931 Trunk:9 CHAN=8: StateChange: END=X CMCSCompleted->CMCSDelete
11:49:40 3586957mS CMTARGET: ISDN BChannel 8: in-service check = 1
11:49:40 3586957mS CMTARGET: ISDN BChannel 8: in-service check = 1
11:49:40 3586957mS CMCallEvt: 0a0064de00000401 0.1025.0 -1 BaseEP: DELETE CMEndpoint f17b82c4 TOTAL NOW=2 CALL_LIST=1
11:49:41 3587216mS RES: Wed 4/11/2015 11:49:42 FreeMem=48664332 (Heap=48411716(1) + Cache=252616) MemObjs=23700(Max 23855) CMMsg=4(5) Buff=5200 1371 1000 7363 5 Links=64365(87000) BTree=12290 CPU=03.31% CPUStats=03.18%/1/4/7550/15563/17090/00.48%/0/03
.02% MCR=0 MCW=0
11:49:41 3587216mS RES2: (SE-E) IP 500 V2 9.1.2.0 build 91 Tasks=61 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=90 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=27(TLS=8) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:49:41 3587216mS RES4: XML MemObjs=63 PoolMem=4876404(2) FreeMem=4861100(0)
11:49:41 3587217mS RES5: CLog MemObjs=34 FreePoolMem(Objs)=3432(66) TotalMem=108800
11:49:41 3587673mS PRN: Line 5: Manual: Line Loopback Active
11:49:41 3587951mS CMARS: Retarget existing BUSY targets - Num of Busy Targets: 1 - Current Form: Main
11:49:42 3588777mS CMMap: PCG::UnmapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8
11:49:42 3588777mS CMMap: a=21.42 b=8.10 M02
11:49:42 3588777mS CMMap: a=21.42 b=0.0 T0
11:49:42 3588778mS CMMap: a=21.42 b=0.0 DTMF::~DTMF freed CMRTUnknown(f52e6100) resource busy 0, total 45
11:49:42 3588779mS CMMap: a=21.42 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail(f52e6100) resource busy 1, total 45
11:49:42 3588779mS CMMap: a=21.42 b=1.65535 T
11:49:42 3588779mS CMMap: PCG::MapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8 type CGTypeDTMF
11:49:42 3588779mS CMMap: a=21.42 b=8.10 M22
11:49:42 3588779mS CMMap: DTMF:layTones g T[28] ,EEEEE
11:49:42 3588780mS CMMap: Started playing tones, cp[312]b1r0 (from g null)
11:49:42 3588780mS CMMap: cp[312]b1r0 SetOperGroup from g null to g null not executed, playing tones in progress ,EEEEE
11:49:44 3590600mS CMMap: PCG::UnmapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8
11:49:44 3590600mS CMMap: a=21.42 b=8.10 M02
11:49:44 3590600mS CMMap: a=21.42 b=0.0 T0
11:49:44 3590601mS CMMap: a=21.42 b=0.0 DTMF::~DTMF freed CMRTUnknown(f52e6100) resource busy 0, total 45
11:49:46 3592717mS RES: Wed 4/11/2015 11:49:48 FreeMem=48664020 (Heap=48411244(1) + Cache=252776) MemObjs=23697(Max 23855) CMMsg=4(5) Buff=5200 1372 1000 7363 5 Links=64360(87000) BTree=12290 CPU=03.73% CPUStats=03.61%/1/5/7550/15632/17090/00.29%/0/02
.96% MCR=0 MCW=0
11:49:46 3592718mS RES2: (SE-E) IP 500 V2 9.1.2.0 build 91 Tasks=61 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=85 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=28(TLS=8) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:49:46 3592718mS RES4: XML MemObjs=63 PoolMem=4876404(2) FreeMem=4861100(0)
11:49:46 3592718mS RES5: CLog MemObjs=34 FreePoolMem(Objs)=3432(66) TotalMem=108800
11:49:47 3593951mS CMARS: Retarget existing BUSY targets - Num of Busy Targets: 1 - Current Form: Main
11:49:47 3593951mS CMARS: Target: Short_Code: N; - Line_Group_ID: 77 - Telephone_Number: NSi5198842310 - Line_Status: CMARS_OUTOFSERVICE
11:49:47 3593951mS CMLineTx: v=5
CMRestart
Line: type=Q931Line 5 Call: lid=0 id=-1 in=0
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
UUI type=User2User [...] [0x00 0x1a 0x00 ]
Display [enu]
Locale: enu
11:49:47 3593951mS CMTARGET: Problem with Line Id: 5 - preselected: 00000000, Unlicenced: 0, OperationalTest: 1, NewCallResourceCheck: -1
11:49:47 3593952mS CMCallEvt: 0000000000000000 0.1026.0 -1 BaseEP: NEW CMEndpoint f17b82c4 TOTAL NOW=3 CALL_LIST=1
11:49:47 3593953mS CMTARGET: ISDN BChannel 8: in-service check = 1
11:49:47 3593953mS CMTARGET: ISDN BChannel 8: in-service check = 1
11:49:47 3593954mS CMARS: FOUND LINE - Line Id: 9 - using line group id: 77 - Short Code: N; - Called Number: 14169671111 - Calling Number: 5198842310
11:49:47 3593954mS CMARS: ModifyCMARSTarget: Short_Code: N; - Line_Group_ID: 77 set line status to CMARS_TRYING
11:49:47 3593954mS CMARS: SetCurrentTarget (TryTarget): Short_Code: N; - Line_Group_ID: 77
11:49:47 3593954mS CMARS: Retarget result=SEND Setup TO LINE
11:49:47 3593954mS CMCallEvt: 0a0064de00000402 0.1026.0 6 Q931 Trunk:9 CHAN=8: StateChange: END=child CMCSIdle->CMCSOffering
11:49:47 3593955mS PRN: Setting configured voice gain for ch 8.
11:49:47 3593955mS CMLineTx: v=9
CMSetup
Line: type=Q931Line 9 Call: lid=0 id=1026 in=0
Called[14169671111] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[5198842310] Type=National Plan=ISDN Pres=Restricted (1)
BC: CMTC=3K1Audio CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=8
Locale: enu
11:49:47 3593955mS CD: CALL: 0.1022.0 BState=Ringing Cut=3 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [Line 9] (0.0) CalledNum=914169671111 () CallingNum=1259 (WITHHELD) Internal=1 Time=25521 AState=Ringing
11:49:47 3593957mS CMMap: a=21.42 b=0.0 DTMF::AllocateRAS allocated CMRTVoicemail(f52e6100) resource busy 1, total 45
11:49:47 3593957mS CMMap: a=21.42 b=1.65535 T
11:49:47 3593958mS CMMap: PCG::MapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8 type CGTypeDTMF
11:49:47 3593958mS CMMap: a=21.42 b=8.10 M22
11:49:47 3593958mS CMMap: DTMF:layTones g T[29] ,EEEEE
11:49:47 3593958mS CMMap: Started playing tones, cp[312]b1r0 (from g null)
11:49:47 3593958mS CMMap: cp[312]b1r0 SetOperGroup from g null to g null not executed, playing tones in progress ,EEEEE
11:49:47 3593959mS ISDNL3Evt: v=9 stacknum=9 State, new=Initiated, old=NullState id=1026
11:49:47 3593960mS ISDNL3Tx: v=9 peb=9
ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=0005(Remote)
Message Type = Setup
InformationElement = BearerCapability
0000 04 03 90 90 a2 .....
InformationElement = CHI
0000 18 03 a9 83 88 .....
InformationElement = CallingPartyNumber
0000 6c 0c 21 a0 35 31 39 38 38 34 32 33 31 30 l.!.5198842310
InformationElement = CalledPartyNumber
0000 70 0c 80 31 34 31 36 39 36 37 31 31 31 31 p..14169671111
InformationElement = Sending Complete
11:49:49 3594997mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1259: Menu Key Pressed 12:I
11:49:49 3594998mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1259: Feature Key Pressed 6CPLFeatureDrop
11:49:49 3594999mS CMCallEvt: 0a0064de000003fe 0.1022.0 6 KW CompRm Bnch.0: StateChange: END=A CMCSRingBack->CMCSCompleted
11:49:49 3594999mS CMExtnEvt: v=8 State, new=PortRecoverDelay old=Alerting,0,0,KW CompRm Bnch
11:49:50 3595000mS CMLOGGING: CALL:2015/11/0411:49,00:00:00,000,1259,O,914169671111,914169671111,KWCompRmBnch,,,1,,"",0,n/a
11:49:50 3595001mS CD: CALL: 0.1022.0 BState=Ringing Cut=2 Music=0.0 Aend="KW CompRm Bnch(1259)" (8.10) Bend="" [Line 9] (0.0) CalledNum=914169671111 () CallingNum=1259 (WITHHELD) Internal=1 Time=26566 AState=Idle
11:49:50 3595001mS CD: CALL: 0.1022.0 Deleted
11:49:50 3595001mS CMExtnEvt: KW CompRm Bnch: CALL LOST (CMCauseNormal)
11:49:50 3595001mS CMExtnEvt: KW CompRm Bnch: Extn(1259) Calling Party Number(1259) Type(CMNTypeInternal)
11:49:50 3595001mS CMExtnEvt: KW CompRm Bnch: CMExtnHandler::SetCurrent( id: 1022->0 )
11:49:50 3595002mS CMCallEvt: 0a0064de000003fe 0.1022.0 -1 KW CompRm Bnch.-1: StateChange: END=X CMCSCompleted->CMCSDelete
11:49:50 3595002mS CMARS: CMARSEndpoint::CallLost(cause=16) - Address: 0a0064de000003fe 0.1024.0 6 ARS for Main - Call State: CMCSAccept
11:49:50 3595003mS CMLineTx: v=9
CMDisconnect
Line: type=Q931Line 9 Call: lid=0 id=1026 in=0
Cause=16, Normal call clearing
11:49:50 3595003mS CMCallEvt: 0a0064de00000402 0.1026.0 -1 Q931 Trunk:9 CHAN=8: StateChange: END=X CMCSOffering->CMCSCompleted
11:49:50 3595003mS CMCallEvt: 0a0064de000003fe 0.1024.0 -1 ARS for Main: StateChange: END=X CMCSAccept->CMCSDelete
11:49:50 3595004mS CMCallEvt: 0a0064de000003fe 0.1024.0 -1 BaseEP: DELETE CMEndpoint f17bb458 TOTAL NOW=2 CALL_LIST=0
11:49:50 3595004mS CMCallEvt: END CALL:6 (f17c5c64)
11:49:50 3595004mS CMTARGET: 0a0064de000003fe 0.1022.0 -1 BaseEP: ~CMTargetHandler f17be8cc ep f17c6180
11:49:50 3595005mS CMCallEvt: 0a0064de000003fe 0.1022.0 -1 BaseEP: DELETE CMEndpoint f17c6180 TOTAL NOW=1 CALL_LIST=0
11:49:50 3595007mS CMMap: PCG::UnmapBChan pcp[312]b1r0 cp_b f48b80bc other_cp_b f52e5fe8
11:49:50 3595007mS CMMap: a=21.42 b=8.10 M02
11:49:50 3595007mS CMMap: a=21.42 b=0.0 T0
11:49:50 3595008mS CMMap: a=21.42 b=0.0 DTMF::~DTMF freed CMRTUnknown(f52e6100) resource busy 0, total 45
11:49:50 3595010mS ISDNL3Evt: v=9 stacknum=9 State, new=DiscReq, old=Initiated id=1026
11:49:50 3595010mS ISDNL3Tx: v=9 peb=9
ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=0005(Remote)
Message Type = Disconnect
InformationElement = CAUSE
0000 08 02 80 90 ....
11:49:52 3597002mS CMExtnEvt: KW CompRm Bnch: Recover Timer reason=CMTRWrapUp
11:49:52 3597002mS CMExtnEvt: v=8 State, new=Idle old=PortRecoverDelay,0,0,KW CompRm Bnch
11:49:52 3597003mS CMExtnTx: v=1259, p1=0
CMVoiceMailStatus
Line: type=DigitalExtn 6 Call: lid=0 id=-1 in=0
Called[KW CompRm Bnch Msgs=0 Old=0 Sav=0] Type=Default (100) Reason=CMDRdirect Calling[00000000] Type=Default Plan=Default
Display [KW CompRm Bnch Msgs=0]
Timed: 04/11/15 11:49
11:49:52 3597673mS PRN: Line 5: Manual: Line Loopback Active
11:49:52 3597718mS RES: Wed 4/11/2015 11:49:52 FreeMem=48692224 (Heap=48411716(1) + Cache=280508) MemObjs=23664(Max 23855) CMMsg=4(5) Buff=5200 1372 1000 7364 5 Links=64353(87000) BTree=12292 CPU=03.87% CPUStats=04.32%/1/5/7550/15517/17090/00.26%/0/02
.95% MCR=0 MCW=0
11:49:52 3597718mS RES2: (SE-E) IP 500 V2 9.1.2.0 build 91 Tasks=61 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=86 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=27(TLS=8) TAPI=1 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
11:49:52 3597718mS RES4: XML MemObjs=63 PoolMem=4876404(2) FreeMem=4861100(0)
11:49:52 3597719mS RES5: CLog MemObjs=35 FreePoolMem(Objs)=3380(65) TotalMem=108800
11:49:53 3598560mS ISDNL3Evt: v=5 p1=5,p2=1001,p3=5,p4=0,s1=


Avaya/Norstar/BCM/Cisco Telephone System Tech

 

[biv343]

For grins, try adding this to the no user source numbers tab: NI2_CALLED_PARTY_TYPE=UNKNOWN

Merge the config and try an outbound call again.

I've found this fixes it 99% of the time when dealing with a NI2 PRI where inbound calls work and outbound calls fail. Some CO switches reject the call if it has a call type of national. That no user source number changes the outbound call type to unknown.

This assumes that the DMS100 CO switch you're connecting to is configured for NI2 on their end and not NI1 or DMS100.

 

[hairlessupportmonkey]

You will probably need to reboot the system adding that to the no user source number.

ACSS - SME
General Geek

 

[Flatts]

Found that "NI2_CALLED_PARTY_TYPE=UNKNOWN" on Tek Tips yesterday, but no change. It is a DMS100.

Bell came back and found issues with the transporting. So hopefully they can fix it today for my cutover tomorrow !

Thanks for the suggestions !

Avaya/Norstar/BCM/Cisco Telephone System Tech