UC Module- Users get dead air

[IPOtech111]

I have a IP500v2 R8.0.46 with a UC Module R8.0.9.3. On a daily basis the voicemail will suddenly fail. When a user calls the voicemail system, whether it is a internal user dialing *17 or a external caller reaching an auto attendant, the call appears to connect to the voicemail but the user does not hear anything they just get dead air. It appears that the .wav files are not being played. Once the VMPro service is restarted all returns to normal for about a day sometimes 2 days then system fails again. The system was originally installed at R8.0.44 with the UC Module at R8.0.8.14. Tech Bulletin 146 for the Q3 maintenance release states under Preferred Edition resolved field issues - "IPOFFICE-30536 VMPro Service on Application Server fails to play prompts, User Gets Dead Air". So I thought upgrading to R8.0.9.3 might resolve the issue but it has not. I have opened SR with Avaya but they state that they do not see any problems in the trace. I wish the debug on the UC Module was more like the debug for a windows based vmpro, the debug for the UC Module seems to be pretty useless. But here is a Monitor trace.

469163573mS CMTARGET: ISDN BChannel 1: in-service check = 1
469163573mS ISDNL3Evt: v=1 stacknum=1 State, new=Present, old=NullState id=20
469163574mS CMLineRx: v=1
CMSetup
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
Called[2868] Type=Unknown (0) Reason=CMDRdirect SndComp Calling[315833xxxx] Type=Unknown Plan=ISDN Pres=Allowed (0)
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=0 chan=1
IE CMIESupplementaryService (3)
Interpretation APDU
rejectAnyUnrecognisedInvokePdu
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLPublicNetLocalUser (2), pd=CMPDNotISDN (1)
469163575mS PRN: Q931Trunk: Found QBChannel to match 0.1 --> 1.2
469163575mS CMCallEvt: 0.9130.0 -1 BaseEP: NEW CMEndpoint f4e3d8c8 TOTAL NOW=1 CALL_LIST=0
469163575mS CMTARGET: ISDN BChannel 1: in-service check = 1
469163576mS CMTARGET: ISDN BChannel 1: in-service check = 1
469163576mS CMCallEvt: CREATE CALL:2040 (f4ea1dd4)
469163576mS CMCallEvt: 0.9131.0 -1 BaseEP: NEW CMEndpoint f4da1680 TOTAL NOW=2 CALL_LIST=0
469163579mS CD: CALL: 1.20.1 BState=Idle Cut=1 Music=0.0 Aend="Line 1" (1.2) Bend="" [] (0.0) CalledNum=2868 () CallingNum=3158339512 () Internal=0 Time=2 AState=Idle
469163579mS CMCallEvt: 1.20.1 2040 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSIdle->CMCSDialInitiated
469163579mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: LOOKUP CALL ROUTE: type=0 called_party=2868 sub= calling=315833xxxx dir=in complete=1 ses=0
469163579mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: SET BESTMATCH: length 0 vs -1 match= dest=Paging
469163580mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: SET BESTMATCH: length 4 vs 0 match=2868 dest=*82
469163580mS CMCallEvt: Priority hike: call 2040 priority 0->1
469163580mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: LOOKUP ICR: DDI= CGPN=315833xxxx (Destination *82 ) => CDPN=*82
469163580mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: ADD TARGET (N): number=*82 type=0 depth=1 nobar=1 setorig=1 ses=0
469163581mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: SYS SC: *82 3 sc=type=VoicemailCollect code=*82, num="Short Codes.Conference" callinfop->sending_complete=1 secondary_dialtone=
469163582mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: ADD VM TARGET
469163582mS CMTARGET: **** 1.20.1 2040 Q931 Trunk:1 CHAN=1: MakeVoicemailTarget pbx=<null> local=1 type=1
469163582mS CMCallEvt: 0.9132.0 -1 BaseEP: NEW CMEndpoint f4e1b328 TOTAL NOW=3 CALL_LIST=1
469163583mS CMTARGET: 0.9132.0 2040 RAS.0: ADD PRIMARY
469163583mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: ADD VM TARGET: SUCCEEDED
469163583mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: INITIAL TARGETING SUCCEEDED
469163583mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: GetNoAnswerTimer:15
469163583mS CMCallEvt: 1.20.1 2040 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSDialInitiated->CMCSDialled
469163584mS CMLineTx: v=1
CMProceeding
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
BChan: slot=0 chan=1
469163584mS CMCallEvt: 0.9131.0 2040 TargetingEP: StateChange: END=B CMCSIdle->CMCSOffering
469163585mS CMCallEvt: 0.9132.0 2040 RAS.0: StateChange: END=T CMCSIdle->CMCSOffering
469163585mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 0->9132 )
469163586mS CMExtnTx: v=RAS, p1=0
CMSetup
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[Short Codes.Conference] Type=Voicemail (102) Reason=CMDRX_Attendant SndComp Calling[315833xxxx] Type=Unknown Plan=ISDN Pres=Allowed (0)
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
BChan: slot=21 chan=42
IE CMIEProgressIndicator (30) cs=CMCSITUT (0), loc=CMLPublicNetLocalUser (2), pd=CMPDNotISDN (1)
IE CMIERespondingPartyNumber (230)(P:0 S:3 T:0 N:1 R:4) number=315833xxxx
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=8 class=CMDeviceISDNTrunk type=2 number=1 channel=1 rx_gain=32 tx_gain=32 ep_callid=20 ipaddr=192.168.1.248 apps=0
IE CMIEIcrPriorityDetail (239) Priority = 1
IE CMIEDIDNumber (245)(P:100 S:100 T:0 N:0 R:4) number=2868
IE CMIEMohSourceId (247) MOH Source = 1
Display [315833xxxx>Short Codes.Conference]
Timed: 09/10/12 08:09
Locale: enu
469163586mS CMMap: a=21.42 b=1.254 T
469163587mS CMExtnRx: v=RAS, p1=0
CMConnect
Line: type=NoLine 0 Call: lid=0 id=-1 in=0
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=Short Codes.Conference
IE CMIERespondingPartyNumber (230)(P:100 S:100 T:102 N:100 R:4) number=Short Codes.Conference
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=8 class=CMDeviceVoicemail type=0 number=0 channel=42 rx_gain=32 tx_gain=32 ep_callid=9132 ipaddr=192.168.1.248 apps=0
469163588mS CMCallEvt: 0.9132.0 2040 RAS.0: StateChange: END=T CMCSOffering->CMCSConnReq
469163588mS CMCallEvt: 0.9131.0 2040 TargetingEP: RequestEnd 0.9132.0 2040 RAS.0
469163588mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: CancelTimer CMTCNoAnswerTimeout
469163589mS CMExtnEvt: v=1011 State, new=Connected old=Idle,0,0,RAS
469163589mS CMCallEvt: 1.20.1 2040 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSDialled->CMCSOGConnReq
469163590mS CMLineTx: v=1
CMConnect
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
BChan: slot=0 chan=1
Display [++fShort Codes.Conference,]
469163590mS CMCallEvt: 0.9131.0 -1 TargetingEP: StateChange: END=X CMCSOffering->CMCSDelete
469163590mS CMCallEvt: 0.9131.0 -1 BaseEP: DELETE CMEndpoint f4da1680 TOTAL NOW=2 CALL_LIST=1
469163591mS CD: CALL: 1.20.1 BState=Connected Cut=3 Music=0.0 Aend="Line 1" (1.2) Bend="Short Codes.Conference(Short Codes.Conference)" [VoiceMail] (21.42) CalledNum=Short Codes.Conference () CallingNum=315833xxxx () Internal=0 Time=15 AState=Connected
469163593mS CMMap: PCG::MapBChan pcp[77]b1r0 cp_b f5736060 other_cp_b 0 type CGTypeSimple
469163593mS CMMap: PCG::MapBChan pcp[32]b1r0 cp_b f576d874 other_cp_b f5736060 type CGTypeSimple
469163593mS CMMap: a=1.2 b=21.42 M1
469163594mS ISDNL3Evt: v=1 stacknum=1 State, new=ICProceeding, old=Present id=20
469163594mS ISDNL3Evt: v=1 stacknum=1 State, new=ConnReq, old=ICProceeding id=20
469163595mS CMLineRx: v=1
CMFacility
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
IE CMIESupplementaryService (3)
Interpretation APDU
rejectAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 67
user 'xxxx' presentation Allowed
469163595mS CMExtnTx: v=RAS, p1=0
CMFacility
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[315833xxxx] Type=Unknown Plan=ISDN Pres=Allowed (0)
BChan: slot=21 chan=42
IE CMIESupplementaryService (3)
Interpretation APDU
rejectAnyUnrecognisedInvokePdu
CallingName.Invoke.CodePageISO8859-1
invokeId 67
user 'xxxx' presentation Allowed
IE CMIERespondingPartyNumber (230)(P:0 S:3 T:0 N:1 R:4) number=315833xxxx
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=8 class=CMDeviceISDNTrunk type=2 number=1 channel=1 rx_gain=32 tx_gain=32 ep_callid=20 ipaddr=192.168.1.248 apps=0
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=xxxx
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=xxxx
469163665mS ISDNL3Evt: v=1 stacknum=1 State, new=Active, old=ConnReq id=20
469163666mS CMLineRx: v=1
CMConnectAck
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
469163666mS CMCallEvt: 1.20.1 2040 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSOGConnReq->CMCSConnected
469163666mS CMTARGET: 1.20.1 2040 Q931 Trunk:1 CHAN=1: ~CMTargetHandler f4d9ffd4 ep f4e3d8c8
469163667mS CMCallEvt: 0.9132.0 2040 RAS.0: StateChange: END=B CMCSConnReq->CMCSConnected
469163668mS CMExtnTx: v=RAS, p1=0
CMConnectAck
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[315833xxxx] Type=Unknown Plan=ISDN Pres=Allowed (0)
BChan: slot=21 chan=42
IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=xxxx
IE CMIERespondingPartyNumber (230)(P:0 S:3 T:0 N:1 R:4) number=315833xxxx
IE CMIEDeviceDetail (231) LOCALE=enu HW=15 VER=8 class=CMDeviceISDNTrunk type=2 number=1 channel=1 rx_gain=32 tx_gain=32 ep_callid=20 ipaddr=192.168.1.248 apps=0
469163668mS VMAIL: SESS 25e: CMD=1 Mailbox=Short Codes.Conference Access=4 !Internal!=N
469163668mS VMAIL: VMAIL Open [VMMESSAGE_OPEN] info :-
469163668mS VMAIL: Flags :- 65 6e 75 00 00 00 07 f8
469163668mS VMAIL: 00 00 00 66 01 00 50 50
469163668mS VMAIL: Mailbox: Short Codes.Conference Access: 4 !Internal!=N Locale: enu
469163669mS VMAIL: Calling Party number: 315833xxxx Display String: 315833xxxx>Short Codes.Conferen
469163669mS VMAIL: Targeted Party number: Called Party number:
469163669mS VMAIL: Calling Party name: Called Party name:
469163669mS VMAIL: DID number 2868 QUEUE: CallAge=0 QueueAge=0 QPos=0 QEta=0 AnnouncmentSync=0
469163669mS VMAIL: Recording Originator: IP addr. of Recording Originator: 0.0.0.0
469163669mS VMAIL: Targeted Party Name:
469163669mS VMAIL: Recording Type: Auto Recording Incoming HuntGroup
469163670mS VMAIL: Answering Party Number: Answering Party Name:
469163670mS VMAIL: Targeted Party Offset: 50
469163670mS VMAIL: Compression Format: input[00] output[00]
469163670mS VMAIL: Validated Recording: No
469163670mS VMAIL: UTC Date:
469163670mS VMAIL: UTC Time:
469163671mS VMAIL: SESS 25e: CMD=9 Mailbox=Short Codes.Conference Access=4 !Internal!=N
469163671mS VMAIL: VMAIL Open [VMMESSAGE_ACTIVE] info :-
469163671mS VMAIL: Flags :- 65 6e 75 00 00 00 07 f8
469163671mS VMAIL: 00 00 00 66 01 80 50 50
469163671mS VMAIL: Mailbox: Short Codes.Conference Access: 4 !Internal!=N Locale: enu
469163672mS VMAIL: Calling Party number: 315833xxxx Display String: 315833xxxx>Short Codes.Conferen
469163672mS VMAIL: Targeted Party number: Called Party number:
469163672mS VMAIL: Calling Party name: Called Party name:
469163672mS VMAIL: DID number 2868 QUEUE: CallAge=0 QueueAge=0 QPos=0 QEta=0 AnnouncmentSync=0
469163672mS VMAIL: Recording Originator: IP addr. of Recording Originator: 0.0.0.0
469163672mS VMAIL: Targeted Party Name:
469163672mS VMAIL: Recording Type: Auto Recording Incoming HuntGroup
469163673mS VMAIL: Answering Party Number: Answering Party Name:
469163673mS VMAIL: Targeted Party Offset: 50
469163673mS VMAIL: Compression Format: input[00] output[00]
469163673mS VMAIL: Validated Recording: No
469163673mS VMAIL: UTC Date:
469163673mS VMAIL: UTC Time:
469163995mS RES: Tue 9/10/2012 08:09:21 FreeMem=57185876(2) CMMsg=6 (8) Buff=5200 950 999 7423 5 Links=6382
469163996mS RES2: IP 500 V2 8.0(46) Tasks=45 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=59 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=1 TCP=15 TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
469179767mS ISDNL3Evt: v=1 stacknum=1 State, new=ReleaseReq, old=Active id=20
469179815mS ISDNL3Evt: v=1 stacknum=1 State, new=NullState, old=ReleaseReq id=20
469179816mS CMLineRx: v=1
CMReleaseComp
Line: type=Q931Line 1 Call: lid=1 id=20 in=1
BChan: slot=0 chan=1
Cause=16, Normal call clearing
469179817mS CMCallEvt: 1.20.1 2040 Q931 Trunk:1 CHAN=1: StateChange: END=A CMCSConnected->CMCSCompleted
469179818mS CMLOGGING: CALL:2012/10/0908:09,00:00:16,000,315833xxxx,I,*82,2868,xxxx,,,0,,""n/a,0
469179818mS CD: CALL: 1.20.1 BState=Connected Cut=2 Music=0.0 Aend="Line 1" (1.2) Bend="Short Codes.Conference(Short Codes.Conference)" [VoiceMail] (21.42) CalledNum=Short Codes.Conference () CallingNum=315833xxxx (xxxx) Internal=0 Time=16242 ASta
e=Idl
469179819mS CD: CALL: 1.20.1 Deleted
469179819mS CMCallEvt: 1.20.1 -1 Q931 Trunk:1 CHAN=1: StateChange: END=X CMCSCompleted->CMCSDelete
469179819mS CMExtnEvt: RAS: CALL LOST (CMCauseNormal)
469179820mS CMCallEvt: 0.9132.0 -1 RAS.0: StateChange: END=X CMCSConnected->CMCSCompleted
469179820mS CMExtnEvt: v=1011 State, new=PortRecoverDelay old=Connected,0,0,RAS
469179820mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
Called[Short Codes.Conference] Type=Voicemail (102) Reason=CMDRX_Attendant Calling[315833xxxx] Type=Unknown Plan=ISDN Pres=Allowed (0)
BChan: slot=21 chan=42
Cause=16, Normal call clearing
469179820mS VMAIL: SESS 25e: CMD=2 Mailbox=Short Codes.Conference Access=4 !Internal!=N
469179820mS VMAIL: VMAIL Open [VMMESSAGE_CLOSE] info :-
469179820mS VMAIL: Flags :- 65 6e 75 00 00 00 07 f8
469179821mS VMAIL: 00 00 10 66 01 80 50 50
469179821mS VMAIL: Mailbox: Short Codes.Conference Access: 4 !Internal!=N Locale: enu
469179821mS VMAIL: Calling Party number: 31583xxxx Display String: 315833xxxx>Short Codes.Conferen
469179821mS VMAIL: Targeted Party number: Called Party number:
469179821mS VMAIL: Calling Party name: Called Party name:
469179821mS VMAIL: DID number 2868 QUEUE: CallAge=0 QueueAge=0 QPos=0 QEta=0 AnnouncmentSync=0
469179822mS VMAIL: Recording Originator: IP addr. of Recording Originator: 0.0.0.0
469179822mS VMAIL: Targeted Party Name:
469179822mS VMAIL: Recording Type: Auto Recording Incoming HuntGroup
469179822mS VMAIL: Answering Party Number: Answering Party Name:
469179822mS VMAIL: Targeted Party Offset: 50
469179822mS VMAIL: Compression Format: input[00] output[00]
469179822mS VMAIL: Validated Recording: No
469179822mS VMAIL: UTC Date:
469179823mS VMAIL: UTC Time:
469179823mS VMAIL: SESS 25e: END Transmit=129 Discards=0 Recv=0 SeqErrs=0 Empty=0 Purges=0
469179823mS CMMap: a=21.42 b=0.0 T0
469179825mS CMExtnEvt: RAS: CMExtnHandler::SetCurrent( id: 9132->0 )
469179825mS CMCallEvt: 0.9132.0 -1 RAS.-1: StateChange: END=X CMCSCompleted->CMCSDelete
469179825mS CMExtnEvt: v=1011 State, new=Idle old=PortRecoverDelay,0,0,RAS
469179825mS CMExtnTx: v=RAS, p1=0
CMReleaseComp
Line: type=RAS 1 Call: lid=0 id=1011 in=0
BChan: slot=21 chan=42
Cause=16, Normal call clearing
469179826mS CMCallEvt: 0.9132.0 -1 BaseEP: DELETE CMEndpoint f4e1b328 TOTAL NOW=1 CALL_LIST=0
469179826mS CMCallEvt: END CALL:2040 (f4ea1dd4)
469179827mS CMTARGET: ISDN BChannel 1: in-service check = 1
469179827mS CMTARGET: ISDN BChannel 1: in-service check = 1
469179827mS CMCallEvt: 1.20.1 -1 BaseEP: DELETE CMEndpoint f4e3d8c8 TOTAL NOW=0 CALL_LIST=0
469179829mS CMMap: PCG::UnmapBChan pcp[32]b1r0 cp_b f576d874 other_cp_b f5736060
469179829mS CMMap: a=1.2 b=21.42 M0
469179829mS CMMap: PCG::UnmapBChan pcp[77]b1r0 cp_b f5736060 other_cp_b 0

 

[tlpeter]

What is the IPaddress of the voicemail pro in manager?


BAZINGA!

I'm not insane, my mother had me tested!

 

[IPOtech111]

192.168.1.249

 

[Westi]

I doubt that it is a programing error (except if the vm pro is programmed as 0.0.0.0) and I would suggest to get a new UCM and replace it as long as you still have warranty on it (hopefully that is the case)

Joe W.

FHandw, ACSS

http://convergednetworks.ca

 

[tlpeter]

192.168.1.249

That is wrong!
It should be 169.254.0.2

BAZINGA!

I'm not insane, my mother had me tested!

 

[IPOtech111]

Even if we have statically assigned the IP address of the UCM to 192.168.1.249?

 

[IPOtech111]

With that known issue stated in the tech bulletin "IPOFFICE-30536 VMPro Service on Application Server fails to play prompts, User Gets Dead Air" does that apply to the UCM being that is says Application Server? To me that just means the linux version of vmpro? This is why I havent already replaced the UCM and was hoping to get a patch from Avaya.

 

[tlpeter]

Even if we have statically assigned the IP address of the UCM to 192.168.1.249?

Yes

BAZINGA!

I'm not insane, my mother had me tested!

 

[IPOtech111]

Ok, I will adjust and see if that helps....We do have other systems out there with UCM's with the IP Address set in Manager to IP address of the Module without any issues. I suppose I should change those as well...I guess I misinterpreted Avaya documentation, which is weird they are always so clear on everything

 

[tlpeter]

When you have a default IPO and you put in the UCM then it will come up with the 169.254.0.2 IPaddress and the docs say that you should not change that!

BAZINGA!

I'm not insane, my mother had me tested!

 

[IPOtech111]

Ahhh, yeah my mistake. Here is what threw me off.

"When a new Unified Communications Module running Voicemail Pro is added to a new system, the system configuration is automatically adjusted to use that voicemail server. However, this should be confirmed by checking the Voicemail Type and Voicemail IP Address settings in the IP Office configuration. If the switch has previously been configured for a specific voicemail server address, those settings are not automatically changed and will need to be manually updated."

The last sentence there I guess I read too quickly and took that as if the Voicemail was configured for a specific address then it needed to be manually updated. Makes sense now though that I read it more carefully. My bad. Thanks for the help. Making that change momentarily, will post back after monitoring the system for a few days.

Thanks

 

[IPOtech111]

Just an update.

I did adjust the voicemail IP address in Manager to 169.254.0.2, no luck issue still persists. I also replaced the UCM with a brand new one, issue still persists. I think we have given up on the UCM and are going to be replacing it with a Windows VMPro server today.

 

[tlpeter]

That is strange as i never had this issue.
You better raise a case.


BAZINGA!

I'm not insane, my mother had me tested!