Voicemail Pro Outcalling R11.0.4 1

[j.flanagan]

I just upgraded one of our customers from embedded voicemail to voicemail pro and I'm trying to get out calling configured. They want a voicemail box to call to one of their cell phones if there is a message left in their afterhours emergency box. I've used the voicemail pro client to set it up so far and I can get it to call out to their desk phones (aka extensions only) However, whenever I try to have it call externally, I can watch System Status and see the call set up and then immediately disappear.




Here's a monitor trace (not sure if I got the filters right)

09:53:12 1034767043mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1304: Menu Key Pressed 12:I
09:53:12 1034767044mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,1304: Feature Key Pressed 6CPLFeatureDrop
09:53:12 1034767045mS CMCallEvt: c0a82a0500000945 263.2373.0 364 Jon.0: StateChange: END=A CMCSConnected->CMCSCompleted
09:53:12 1034767045mS CMExtnEvt: v=1 State, new=PortRecoverDelay old=Connected,0,0,Jon
09:53:12 1034767048mS CMExtnEvt: Jon: CALL LOST (CMCauseNormal)
09:53:12 1034767048mS CMExtnEvt: Jon: Extn(1304) Calling Party Number(1304) Type(CMNTypeInternal)
09:53:12 1034767048mS CMExtnEvt: Jon: CMExtnHandler::SetCurrent( id: 2373->0 )
09:53:12 1034767049mS CMCallEvt: c0a82a0500000945 263.2373.0 -1 Jon.-1: StateChange: END=X CMCSCompleted->CMCSDelete
09:53:12 1034767050mS CMExtnEvt: RAS: CALL LOST (CMCauseNormal)
09:53:12 1034767050mS CMCallEvt: c0a82a0500000947 0.2375.0 -1 RAS.0: StateChange: END=X CMCSConnected->CMCSCompleted
09:53:12 1034767050mS CMExtnEvt: v=1012 State, new=PortRecoverDelay old=Connected,0,0,RAS
09:53:12 1034767051mS CMMap: a=21.11 b=0.0 T0
09:53:12 1034767052mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 2375->0 )
09:53:12 1034767053mS CMCallEvt: c0a82a0500000947 0.2375.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
09:53:12 1034767053mS CMExtnEvt: v=1012 State, new=Idle old=PortRecoverDelay,0,0,RAS
09:53:12 1034767053mS PRN: CMQoSHandler::CheckQoSAlarm(): QoS data not available - handler is not on an extension or a line
09:53:12 1034767053mS CMCallEvt: c0a82a0500000947 0.2375.0 -1 BaseEP: DELETE CMEndpoint f1786a94 TOTAL NOW=1 CALL_LIST=0
09:53:12 1034767054mS CMCallEvt: END CALL:364 (f1798c64)
09:53:12 1034767055mS PRN: QOS Data: Call ID=364 Device=Phone(Number=1304, BaseExtn=1304) IP Address:192.168.42.15 Peer IP Address:192.168.42.5 Call Duration=26s
09:53:12 1034767055mS PRN: QOS Data Continued Jitter: Max=0ms Avg=0ms Round Trip Delay: Max=3ms Avg=3ms Packet Loss: Max=0/1000 Avg=0/1000
09:53:12 1034767055mS CMCallEvt: c0a82a0500000945 263.2373.0 -1 BaseEP: DELETE CMEndpoint f17a9fdc TOTAL NOW=0 CALL_LIST=0
09:53:12 1034767058mS CMMap: PCG::UnmapBChan pcp[55]b1r0 cp_b f5336dc8 other_cp_b f5347338
09:53:12 1034767058mS CMMap: a=0.1 b=21.11 M02
09:53:12 1034767059mS PRN: rtpRelayFilter close rc: 0 rtpRelayId: 1
09:53:12 1034767059mS CMMap: PlatformConnectionAudioSAP:isconnectRtpFilter rtpRelayId: 1 Close success
09:53:12 1034767059mS CMMap: PCG::UnmapBChan pcp[475]b0r1 cp_b 0 other_cp_b 0
09:53:12 1034767060mS CMMap: a=0.1 b=0.0 Mapper::FreeCodec freed CMRTVocoder(f52fd898) resource busy 1, total 42
09:53:14 1034769049mS CMExtnEvt: Jon: Recover Timer reason=CMTRWrapUp
09:53:14 1034769049mS CMExtnEvt: v=1 State, new=Idle old=PortRecoverDelay,0,0,Jon
09:53:14 1034769573mS RES: Tue 7/9/2021 09:53:14 FreeMem=55380056 Heap=54939700(3) Cache=440356 MemObjs=11503(Max 12536) CMMsg=8(9) ASN=0 Buff=5200 1364 1000 7404 5 Links=54036(54290) BTree=727(1289) CB=6064 MCT=0 CPU=08.92% CPUStats=08.01%/1/5/2438/1638
8/18081/00.04%/0/02.63% MCR=0
09:53:14 1034769573mS RES2: IP 500 V2 11.0.4.3.0 build 3 Tasks=61 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=15+71 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=29(TLS=10 OFF=0) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
09:53:14 1034769574mS RES4: XML MemObjs=8 PoolMem=4748404(2) FreeMem=4736284(0) HeapUsed=0
09:53:14 1034769574mS RES5: CLog MemObjs=272 FreePoolMem(Objs)=7168(128) TotalMem=22400 StringsTotalMem=103600
09:53:15 1034770233mS CMMap: a=21.11 b=1.65534 T
09:53:15 1034770235mS CMCallEvt: 0000000000000000 0.2376.0 -1 BaseEP: NEW CMEndpoint f17a9fdc TOTAL NOW=1 CALL_LIST=0
09:53:15 1034770235mS CMCallEvt: CREATE CALL:365 (f1798c64)
09:53:15 1034770235mS CMCallEvt: 0000000000000000 0.2377.0 -1 BaseEP: NEW CMEndpoint f17b4550 TOTAL NOW=2 CALL_LIST=0
09:53:15 1034770237mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 0->2376 )
09:53:15 1034770238mS CMCallEvt: c0a82a0500000948 0.2376.0 365 RAS.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
09:53:15 1034770238mS CMExtnEvt: v=1012 State, new=Dialling old=Idle,0,0,RAS
09:53:15 1034770238mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=Voicemail calling_sub= dir=out complete=0 ses=0
09:53:15 1034770238mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
09:53:15 1034770239mS CMCallEvt: c0a82a0500000948 0.2376.0 365 RAS.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
09:53:15 1034770242mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: LOOKUP CALL ROUTE: GID=0 type=111 called_party=97275045706 sub= calling=OUTBOUND ALERT calling_sub= dir=out complete=1 ses=0
09:53:15 1034770242mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: ADD TARGET (N): number=97275045706 type=111 depth=1 nobar=1 setorig=1 ses=0
09:53:15 1034770242mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: SYS SC: 97275045706 2 7275045706 sc=type=Dial code=9N, num=N callinfop->sending_complete=1 secondary_dialtone=
09:53:15 1034770243mS CMARS: FindActiveARSByGroupID GroupID=50 - Found
09:53:15 1034770243mS CMARS: MakeCallTarget - Called Number: 7275045706
09:53:15 1034770243mS CMCallEvt: 0000000000000000 0.2378.0 -1 BaseEP: NEW CMEndpoint f174ab64 TOTAL NOW=3 CALL_LIST=1
09:53:15 1034770244mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: CancelTimer CMTCDialToneTimeout
09:53:15 1034770244mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: INITIAL TARGETING SUCCEEDED
09:53:15 1034770244mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: GetNoAnswerTimer:25
09:53:15 1034770245mS CMCallEvt: c0a82a0500000948 0.2376.0 365 RAS.0: StateChange: END=A CMCSDialling->CMCSDialled
09:53:15 1034770245mS CMExtnEvt: v=1012 State, new=Proceeding old=Dialling,0,0,RAS
09:53:15 1034770245mS CMCallEvt: 0000000000000000 0.2377.0 365 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
09:53:15 1034770246mS CMCallEvt: 0000000000000000 0.2378.0 365 ARS for Main: StateChange: END=T CMCSIdle->CMCSOffering
09:53:15 1034770246mS CMCallEvt: 0000000000000000 0.2377.0 365 TargetingEP: RequestEnd 0000000000000000 0.2378.0 365 ARS for Main
09:53:15 1034770246mS CMTARGET: c0a82a0500000948 0.2376.0 365 RAS.0: CancelTimer CMTCNoAnswerTimeout
09:53:15 1034770247mS CMCallEvt: 0000000000000000 0.2378.0 365 ARS for Main: StateChange: END=B CMCSOffering->CMCSOverlapRecv
09:53:15 1034770247mS CMARS: FORM: Main - Received Number: 7275045706
09:53:15 1034770248mS CMARS: FOUND A SHORT CODE - short_code: 727N; - Tel: 1727N - Called_Party: 17275045706 - Line Group Id: 1
09:53:15 1034770248mS CMARS: SetCurrentTarget: Short_Code: 727N; - Line_Group_ID: 1
09:53:15 1034770248mS CMARS: FindActiveARSByGroupID GroupID=1 - Not Found
09:53:15 1034770248mS CMLRQ: FindActiveLRQByGroupID GroupID=1 - Not Found
09:53:15 1034770248mS CMCallEvt: 0000000000000000 0.2379.0 -1 BaseEP: NEW CMEndpoint f1753c30 TOTAL NOW=4 CALL_LIST=1
09:53:15 1034770249mS CMTARGET: ISDN BChannel 23: in-service check = 1
09:53:15 1034770250mS CMARS: ModifyCMARSTarget: Short_Code: 727N; - Line_Group_ID: 1 set line status to CMARS_TRYING
09:53:15 1034770251mS CMARS: FOUND LINE - Line Id: 1 - using line group id: 1 (code 727N;, line 1) - Called Number: 17275045706 - Calling Number: OUTBOUND ALERT
09:53:15 1034770251mS CMARS: SEND Setup TO LINE
09:53:15 1034770251mS CMCallEvt: c0a82a050000094b 0.2379.0 365 Q931 Trunk:1 CHAN=23: StateChange: END=child CMCSIdle->CMCSOffering
09:53:15 1034770251mS PRN: Setting configured voice gain for ch 23.
09:53:15 1034770251mS T1DSP: PRIU DSP 1: channel 23 (timeslot 46), restore gains tx 10, rx 10
09:53:15 1034770251mS CMCallEvt: 0000000000000000 0.2377.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
09:53:15 1034770252mS CMCallEvt: 0000000000000000 0.2377.0 -1 BaseEP: DELETE CMEndpoint f17b4550 TOTAL NOW=3 CALL_LIST=1
09:53:15 1034770254mS ISDNL3Evt: v=1 stacknum=1 State, new=Initiated, old=NullState id=2379
09:53:15 1034770330mS ISDNL3Evt: v=1 stacknum=1 State, new=Proceeding, old=Initiated id=2379
09:53:15 1034770331mS CMARS: LINE ep Received: CMProceeding - child->state = CMCSOffering - ARS Call State = CMCSOverlapRecv
09:53:15 1034770331mS CMARS: LINE IS NOW THE B END OF THE CALL - CMARSEndpoint::RequestEnd()
09:53:15 1034770331mS CMARS: CMARSEndpoint::CallLost(cause=124) - Address: c0a82a0500000948 0.2378.0 365 ARS for Main - Call State: CMCSOverlapRecv
09:53:15 1034770332mS CMCallEvt: c0a82a0500000948 0.2378.0 -1 ARS for Main: StateChange: END=X CMCSOverlapRecv->CMCSDelete
09:53:15 1034770333mS CMCallEvt: c0a82a050000094b 0.2379.0 365 Q931 Trunk:1 CHAN=23: StateChange: END=B CMCSOffering->CMCSAccept
09:53:15 1034770333mS CMCallEvt: c0a82a0500000948 0.2378.0 -1 BaseEP: DELETE CMEndpoint f174ab64 TOTAL NOW=2 CALL_LIST=1
09:53:15 1034770335mS CMMap: PCG::MapBChan pcp[55]b1r0 cp_b f5336dc8 other_cp_b 0 type CGTypeSimple
09:53:15 1034770335mS CMMap: PCG::MapBChan pcp[121]b1r0 cp_b f52f2784 other_cp_b f5336dc8 type CGTypeSimple
09:53:15 1034770335mS CMMap: a=21.11 b=1.24 M12
09:53:15 1034770730mS ISDNL3Evt: v=1 stacknum=1 State, new=ReleaseReq, old=Proceeding id=2379
09:53:15 1034770791mS ISDNL3Evt: v=1 stacknum=1 State, new=NullState, old=ReleaseReq id=2379
09:53:15 1034770791mS CMCallEvt: c0a82a050000094b 0.2379.0 365 Q931 Trunk:1 CHAN=23: StateChange: END=B CMCSAccept->CMCSCompleted
09:53:15 1034770793mS CMExtnEvt: RAS: CALL LOST (CMCauseBusy)
09:53:15 1034770793mS CMCallEvt: c0a82a0500000948 0.2376.0 -1 RAS.0: StateChange: END=X CMCSDialled->CMCSCompleted
09:53:15 1034770794mS CMExtnEvt: v=1012 State, new=PortRecoverDelay old=Proceeding,0,0,RAS
09:53:15 1034770794mS CMMap: a=21.11 b=0.0 T0
09:53:15 1034770795mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 2376->0 )
09:53:15 1034770796mS CMCallEvt: c0a82a0500000948 0.2376.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
09:53:15 1034770796mS CMExtnEvt: v=1012 State, new=Idle old=PortRecoverDelay,0,0,RAS
09:53:15 1034770797mS CMTARGET: c0a82a0500000948 0.2376.0 -1 BaseEP: ~CMTargetHandler f17ae5d4 ep f17a9fdc
09:53:15 1034770797mS CMCallEvt: c0a82a0500000948 0.2376.0 -1 BaseEP: DELETE CMEndpoint f17a9fdc TOTAL NOW=1 CALL_LIST=0
09:53:15 1034770797mS CMCallEvt: c0a82a050000094b 0.2379.0 -1 Q931 Trunk:1 CHAN=23: StateChange: END=X CMCSCompleted->CMCSDelete
09:53:15 1034770797mS CMCallEvt: END CALL:365 (f1798c64)
09:53:15 1034770798mS CMTARGET: ISDN BChannel 23: in-service check = 1
09:53:15 1034770798mS CMCallEvt: c0a82a050000094b 0.2379.0 -1 BaseEP: DELETE CMEndpoint f1753c30 TOTAL NOW=0 CALL_LIST=0
09:53:15 1034770800mS CMMap: PCG::UnmapBChan pcp[55]b1r0 cp_b f5336dc8 other_cp_b f52f2784
09:53:15 1034770800mS CMMap: a=1.24 b=21.11 M02
09:53:15 1034770800mS CMMap: PCG::UnmapBChan pcp[121]b1r0 cp_b f52f2784 other_cp_b 0

********** SysMonitor v11.0.4.5.0 build 3 [connected to 10.10.10.30 (TSS IPO)] **********
09:53:19 1034774001mS PRN: Monitor Status IP 500 V2 11.0.4.3.0 build 3
09:53:19 1034774001mS PRN: LAW=U PRI=1, BRI=0, ALOG=4, VCOMP=42, MDM=0, WAN=0, MODU=0 LANM=0 CkSRC=1 VMAIL=1(VER=3 TYP=1) 1-X=0 CALLS=0(TOT=365)
09:53:19 1034774574mS RES: Tue 7/9/2021 09:53:19 FreeMem=55378732 Heap=54939700(3) Cache=439032 MemObjs=11508(Max 12536) CMMsg=8(9) ASN=0 Buff=5200 1363 1000 7404 5 Links=54038(54290) BTree=728(1289) CB=6063 MCT=0 CPU=08.92% CPUStats=07.22%/1/5/2438/1658
8/18081/00.03%/0/02.64% MCR=0
09:53:19 1034774575mS RES2: IP 500 V2 11.0.4.3.0 build 3 Tasks=61 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=14+71 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=30(TLS=10 OFF=0) TAPI=0 Partner=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
09:53:19 1034774575mS RES4: XML MemObjs=8 PoolMem=4748404(2) FreeMem=4736284(0) HeapUsed=0
09:53:19 1034774575mS RES5: CLog MemObjs=272 FreePoolMem(Objs)=7168(128) TotalMem=22400 StringsTotalMem=103600

 

[Okkie26]

Make sure the VM pro is allowed to make aoutside calls

Check manager > system > voicemail and tick 'external calls' (oe something in those lines)

 

[derfloh]

Looks like if it was... If it wasn't you wouldn't see ISDN L3 messages.

For me it looks like if you don't set a caller ID and the provider declines the call. You should add S172...... To the ARS short code. But be aware that it will also affect users dialing outbound.

IP Office remote service
IP Office certificate check
CLI based call blocking
SCN fallback over PSTN

 

[j.flanagan]

Derfloh,
You were right. That was the issue. The system was setup to show the calling parties DID. Voicemail Pro wasn't showing a caller ID and was getting blocked by the carrier. I just set a new ARS table to use 8N and anything dialing out with that short code shows the main number now. Thanks for the help.

 

[derfloh]

Thanks for confirming

IP Office remote service
IP Office certificate check
CLI based call blocking
SCN fallback over PSTN

 

[IPGuru]

IIRC pitting an 'i' as either a prefix or potfix to the number in the incomming call route will get the callers cli trasfered through when the VM makes an outbound call, but only if you have level 5 cli presentation enabled.


Do things on the cheap & it will cost you dear

Avaya Remote Support Engineer (A.R.S.E)