Voicemail Not Picking Up

[h382]

406v2 on 4.1.95011 (patched last week to try and resolve issue)
VM Server on 4.1.27


Older site I had upgraded to a new 406v2(403 previously)

They have Voicemail Pro running on XP, that I recently changed over to 2K3 to try and fix this issue.

The issue is simple, after so long, could be 20 minutes, could be 1 day, the voicemail service is still started, but won't pickup. Callers will hear busy/dead-air.

This wasn't an issue until we upgraded them from a 403 and 3.0 to a 406v2 and 4.1

To fix the issue, I have to restart the Voicemail Pro Service. The licenses show valid. I have an incoming call route pointed to Voicemail to test, and when they are experiencing this issue, the call doesn't even show up in System Status.

Any ideas?

 

[h382]

BTW. They have 8 VM Ports. It shows congestion count of 24, even though I know they haven't maxed out these ports.

I believe there was a Tech Bullentin on VM Ports locking up. But, I have changed the setting in regards to call waiting. I have also tried to installed 4.0.18 with the patch, and the issue still occurs.

 

[ronromano]

When the calls are not showing up in SSA, what happens when a user checks voicemail?

 

[h382]

They get dead air. Sometimes it's dead air that eventually turns into a busy signal.

 

[ronromano]

Sure sounds like the problem that the patch you have addresses. However in the cases of this I have had to deal with, restarting the service would not help, only a reboot of the IPO helped. The only other thing that come to mind is make sure there are no IP address conflicts because I have seen this same problem when that happens.

 

[h382]

I thought for sure the patch would fix it. Then I thought for sure that moving the VMServer to a 2k3 box would fix it. Actually since moving it to 2k3, it's been happening a lot more often.

I'm actually waiting until it happens again, so I can watch monitor and see what it says when they dial *17. Even when it's not working, System Status shows they have 8 ports of VM available.

The XP Box and the 2K3 box it was on both have static IP addresses, and the DHCP addresses are in a different range.(on the same subnet)

 

[h382]

The Tech Bulletin says the patch along with upgrading the VM Pro to 4.1.26 is one of the options for the fix. Well, I have 4.1.27, I wasn't aware there was a .26

?

 

[ronromano]

I'm on 4.1.27. No problems thus far.

 

[h382]

Here is what monitor says after this issue starts happening.. This is a random problem, and I just had it happen at another one of my sites after a merged config. It had never happened there before until Friday.

70150127mS RES: Fri 29/2/2008 15:54:02 FreeMem=46655200(99) CMMsg=5 (5) Buff=100 616 500 1046 5 Links=6403
70150720mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: TimerExpired cause=CMTCNoAnswerTimeout
70150721mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ActionNoAnswerTimeout()
70150721mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget NOANSWER EXCEPTED=00000001 ValidTargets=1
70150721mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget on target_cfg_user=Serena Torres
70150722mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD USER: Serena Torres depth=1 disallow_cw=0 dnd=0 real_call=1 type(CMNTypeUnknown) incl(0x1) excpt(0x1), allow_redir(1) remote=00000000
70150722mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: SELECT: TRY VOICEMAIL orig_hg() orig_user(1926)
70150722mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET
70150723mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET: FAILED availability=0
70150724mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: VM targeting failed. Remaining on final target Serena Torres
70150724mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15
70165724mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: TimerExpired cause=CMTCNoAnswerTimeout
70165725mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ActionNoAnswerTimeout()
70165725mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget NOANSWER EXCEPTED=00000001 ValidTargets=1
70165725mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget on target_cfg_user=Serena Torres
70165726mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD USER: Serena Torres depth=1 disallow_cw=0 dnd=0 real_call=1 type(CMNTypeUnknown) incl(0x1) excpt(0x1), allow_redir(1) remote=00000000
70165726mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: SELECT: TRY VOICEMAIL orig_hg() orig_user(1926)
70165726mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET
70165727mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET: FAILED availability=0
70165728mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: VM targeting failed. Remaining on final target Serena Torres
70165728mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15
70167241mS ISDNL3Evt: v=1 stacknum=1 State, new=ReleaseReq, old=Received id=9
70167273mS ISDNL3Evt: v=1 stacknum=1 State, new=NullState, old=ReleaseReq id=9
70167274mS CMCallPkt: v=0
CMReleaseComp
Line: type=Q931Line 1 Call: lid=0 id=9 in=1
BChan: slot=0 chan=1
Cause=16, Normal call clearing

 

[intrigrant]

I think the DbgOut.txt file may be more informational.
Do you have th program DbgOut.exe? This enables you to see very detailed what is going on inside VM Pro and it may shine a light on your problem.
You can find more info here:

http://marketingtools.avaya.com/knowledgebase/ipoffice41en/tools/debug/index.htm

NIHIL NOVI SUB SOLE

 

[ronromano]

Many times when I have issues like this it turns out to be corrupt users. Does it happen consistantly on a particular user?

 

[h382]

i will check out dbgout, thanks.

also.. i have tried a complete rebuild from scratch also, thinking it might have just been corruption, but it still happens after the rebuild. unfortunately I cannot recreate the issue at will, so I am forced to wait until it breaks to gather more information. and its always ok over the weekend.

 

[ronromano]

Thing showing up in system status are delayed. If you watch monitor you will see things instantly. Whith pots lines for instace with CID, you won't see the call in SSA until the CID is recieved. I found this out when trouble shooting a PRI problem. The call would be rejected right away and SSA would show nothing so I assumed it was not hitting the IPO but when monitor was opened you could see the call.

I think the trace above is late in the call, I would like to see the whole call.

 

[h382]

Ok here you go

70120695mS PRN: Found QBChannel to match 0.1 --> 2.2
70120695mS CMCallEvt: 0.4268.0 -1 BaseEP: NEW CMEndpoint fec93a2c TOTAL NOW=3 CALL_LIST=1
70120696mS CMCallEvt: CREATE CALL:894
70120696mS CMCallEvt: 0.4269.0 -1 BaseEP: NEW CMEndpoint fec876a4 TOTAL NOW=4 CALL_LIST=1
70120705mS PRN: Setting configured voice gain on ch 1.
70120705mS CD: CALL: 1.9.1 State=0 Cut=1 Music=0.0 Aend="Line 1" (2.2) Bend="" [] (0.0) CalledNum=1926 () CallingNum=4159550239 () Internal=0 Time=9 AState=0
70120706mS CMCallEvt: 1.9.1 894 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated
70120706mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: LOOKUP CALL ROUTE: type=0 called_party=1926 sub= calling=4159550239 in=1 complete=1 ses=0
70120706mS CMTARGET: INCOMING EXTERNAL CALL ROUTE
70120707mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: SET BESTMATCH: length 4 vs 0 match=4153731926 dest=1926
70120707mS CMCallEvt: PRIORITY HIKE:894 0->1
70120708mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: LOOKUP INCOMING CALL ROUTE: calling party is 4159550239. Matched profile Destination 1926
70120708mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD TARGET (N): number=1926 type=0 depth=1 nobar=1 setorig=1 ses=0
70120708mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: FoundKnownSystemTargets 1926 (ses: 0)
70120709mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: SET USER: Serena Torres orig=1
70120709mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD USER: Serena Torres depth=2 disallow_cw=0 dnd=0 real_call=1 type(CMNTypeUnknown) incl(0x0) excpt(0x0), allow_redir(1) remote=00000000
70120710mS CMCallEvt: 0.4270.0 -1 BaseEP: NEW CMEndpoint fec854d4 TOTAL NOW=5 CALL_LIST=2
70120714mS CMTARGET: 0.4270.0 894 Serena Torres.0: ADD PRIMARY
70120714mS PRN: BasicFindBestInCallRouteMatch returns(2)
70120714mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: INITIAL TARGETING SUCCEEDED
70120715mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15
70120715mS CMCallEvt: 1.9.1 894 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSDialInitiated->CMCSDialled
70120716mS CMLineTx: v=1
CMProceeding
Line: type=Q931Line 1 Call: lid=0 id=9 in=1
BChan: slot=0 chan=1
70120717mS CMCallEvt: 0.4269.0 894 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
70120719mS CMCallEvt: 0.4270.0 894 Serena Torres.0: StateChange: END=T CMCSIdle->CMCSOffering
70120719mS CMExtnTx: v=1926, p1=0
CMSetup
Line: type=DigitalExtn 5 Call: lid=0 id=4270 in=0
Called[1926] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[4159550239] Type=Unknown Plan=ISDN Pres=Allowed (0)
BC: CMTC=3K1Audio CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIERespondingPartyNumber (230)(P:0 S:1 T:0 N:1 R:4) number=4159550239
IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=4 class=CMDeviceISDNTrunk type=2 number=1 channel=1 gain=32
IE CMIECalledPartyName (224) Serena Torres
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:0 N:0 R:4) number=1926
Display [4159550239>Serena Torres]
Timed: 29/02/08 15:53
Locale: enu
70120720mS CMExtnRx: v=1926, p1=0
CMAlerting
Line: type=DigitalExtn 5 Call: lid=0 id=4270 in=0
70120720mS CMCallEvt: 0.4270.0 894 Serena Torres.0: StateChange: END=T CMCSOffering->CMCSRinging
70120721mS CMCallEvt: 0.4269.0 894 TargetingEP: StateChange: END=B CMCSOffering->CMCSRinging
70120722mS CMCallEvt: 1.9.1 894 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSDialled->CMCSRingBack
70120724mS CMLineTx: v=1
CMAlerting
Line: type=Q931Line 1 Call: lid=0 id=9 in=1
BChan: slot=0 chan=1
70120726mS CD: CALL: 1.9.1 State=1 Cut=1 Music=2.0 Aend="Line 1" (2.2) Bend="" [Serena Torres(1926)] (0.0) CalledNum=1926 (Serena Torres) CallingNum=4159550239 () Internal=0 Time=30 AState=1
70120728mS CMMap: a=2.2 b=0.0 R1
70120729mS ISDNL3Evt: v=1 stacknum=1 State, new=ICProceeding, old=Present id=9
70120729mS ISDNL3Evt: v=1 stacknum=1 State, new=Received, old=ICProceeding id=9
70121128mS RES: Fri 29/2/2008 15:53:33 FreeMem=46640132(83) CMMsg=5 (5) Buff=100 616 499 1046 5 Links=6390
70130715mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: TimerExpired cause=CMTCCoverageTimeout
70130716mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15

********** SysMonitor v6.1 (9) [connected to 10.50.45.41 (SFOIP406v2)] **********

70131535mS PRN: Monitor Status IP 406 DS 4.1(95011)
70131535mS PRN: LAW=U PRI=1, BRI=0, ALOG=0, ADSL=0 VCOMP=0, MDM=0, WAN=0, MODU=3 LANM=0 CkSRC=1 VMAIL=0(VER=0 TYP=1) CALLS=2(TOT=894)
70135716mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: TimerExpired cause=CMTCNoAnswerTimeout
70135717mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ActionNoAnswerTimeout()
70135717mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget NOANSWER EXCEPTED=00000001 ValidTargets=1
70135717mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: Retarget on target_cfg_user=Serena Torres
70135718mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD USER: Serena Torres depth=1 disallow_cw=0 dnd=0 real_call=1 type(CMNTypeUnknown) incl(0x1) excpt(0x1), allow_redir(1) remote=00000000
70135718mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: SELECT: TRY VOICEMAIL orig_hg() orig_user(1926)
70135718mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET
70135719mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: ADD VOICEMAIL TARGET: FAILED availability=0
70135719mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: VM targeting failed. Remaining on final target Serena Torres
70135720mS CMTARGET: 1.9.1 894 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15
70141251mS CMExtnRx: v=1905, p1=0
CMReleaseComp

 

[h382]

To me.. It seems as if the 406 is losing its connection to the VM Pro Service for some reason. I do not know what the catalyst that causes this is, but a simple restart of the service fixes it, albeit temporarily. Right now it's been fine all weekend. Last time it went down was around 10:30am on Friday. But that was the 3rd time since 7am Friday morning it happened.

 

[tlpeter]

I am pretty sure there is no connection with the vmserver

70131535mS PRN: LAW=U PRI=1, BRI=0, ALOG=0, ADSL=0 VCOMP=0, MDM=0, WAN=0, MODU=3 LANM=0 CkSRC=1 VMAIL=0(VER=0 TYP=1) CALLS=2

That is why it does not work
Check your settings in the system tab
Check the ipadres in it and on the server
Check your licenses


ACA - Implement IP Office
ACA - Voice Services Management
______________
Women and cats can do as they please and men and dogs should relax and get used to the idea!

 

[h382]

See, that's the problem. It acts like it forgets where VM is at.

VM Server is statically set at .40, the IP Office is .41 also set statically.
Licenses are valid, have always shown valid.
VM Tab is set to PC, with the .40 address in there.

I have 6 other sites with this same exact setup, with no issues. Although like I mentioned in a post earlier, my NJ site had this same issue happen once on Friday after a merge config. First and only time it has ever happened there.

 

[ProviderReborn]

Run the voicemail pro services as local and interact with desktop.
Run it and when you get the issue see if in the log out put it shows as running unlicensed. The thing is it wont show until the lics have been invalid for 2 hours.

Also check PC CPU is not maxing out and killing the VM services (I have seen this before)
Also the addresses its not possible some thing else is powering up with either the .40 or .41 address.

A list of some things to check.

ACA - IP Office Implement
ACA - IP Telephony
CCENT - Cisco ICND1
CCNA - Working towards.

 

[h382]

Have already started the services to interact with desktop, waiting for it to break again to see what it says.

One thing to note is that Thursday night, I unistalled the VM Server on the .40 box, and installed it on .11 which is one of our application servers. The issue still occurred after installing voicemail on a completely different machine. The new machine was windows 2k3, and not XP like .40 was.

Also, I find it unlikely something else is starting up with .40 address. There is DHCP on the network, but the scope starts at .100 All servers and the IPO are always statically set at .40/.41 at every office. Printers are .50's etc. IP Addressing is pretty clean and uniform at every office.

 

[tlpeter]

Try to connect your voicemail pc straight on the ipoffice (if that is not the case)
It could be a blocked port (50791)



ACA - Implement IP Office
ACA - Voice Services Management
______________
Women and cats can do as they please and men and dogs should relax and get used to the idea!