I have no idea what is happening.A 9.1 system with VM Pro stopped working *17 and visual voice keys said "Unobtainable". So I changed it to Embedded VM and the same thing happens. Here is a monitor of the Embedded VM mode ext. 103 dialing
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[103] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 12 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Lynn
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Lynn
17:10:26 259105mS CMCallEvt: c0a80ac8000003eb 259.1003.0 1 Lynn.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
17:10:26 259105mS CMExtnEvt: v=3 State, new=Dialling old=Idle,0,0,Lynn
17:10:26 259106mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=103 dir=out complete=0 ses=0
17:10:26 259106mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:26 259106mS CMCallEvt: c0a80ac8000003eb 259.1003.0 1 Lynn.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
17:10:26 259109mS CMExtnTx: v=103, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
CMSecurityElement RX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
CMSecurityElement TX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
Timed: 07/09/15 17:10
17:10:26 259109mS H323Evt: PortmAvayaH323Phone:
ortmAvayaH323PhoneDelay: 103 - delay disabled
17:10:26 259109mS CMExtnTx: v=103, p1=8008
CMFacility
Line: type=IPLine 250 Call: lid=259 id=3 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
17:10:26 259110mS CMExtnTx: v=103, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Timed: 07/09/15 17:10
17:10:26 259110mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[*] Type=Default (100) Reason=CMDRdirect Keypad[*]
17:10:26 259110mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:26 259111mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=* sub= calling=103 dir=out complete=0 ses=0
17:10:26 259111mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=* type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:26 259114mS CD: CALL: 259.1003.0 BState=Idle Cut=0 Music=0.0 Aend="Lynn(103)" (0.0) Bend="" [] (0.0) CalledNum=* () CallingNum=103 (Lynn) Internal=1 Time=331 AState=Dialling
17:10:26 259115mS H323Evt: SESS 1 SetOperational local 192.168.10.200:0 remote 0.0.0.0:0 to 0
17:10:26 259116mS H323Evt: SESS 1 SetRemUDP 0 -> 52644
17:10:26 259506mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,103: Digit Key Pressed 1
17:10:26 259506mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[1] Type=Default (100) Reason=CMDRdirect Keypad[1]
17:10:26 259506mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:26 259507mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=*1 sub= calling=103 dir=out complete=0 ses=0
17:10:26 259507mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=*1 type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:27 260081mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,103: Digit Key Pressed 7
17:10:27 260081mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=*17 sub= calling=103 dir=out complete=0 ses=0
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=*17 type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: SYS SC: *17 3 sc=type=VoicemailCollect code=*17, num=?U callinfop->sending_complete=0 secondary_dialtone=
17:10:27 260083mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD VM TARGET
17:10:27 260083mS CMTARGET: **** c0a80ac8000003eb 259.1003.0 1 Lynn.0: MakeVoicemailTarget pbx=<null> local=1 type=3
17:10:27 260083mS CMMap: Mapper::AllocateCodec unable to allocate resource
17:10:27 260083mS CMCallEvt: Cannot reserve a codec for Aend, aend is c0a80ac8000003eb 259.1003.0 1 Lynn.0
17:10:27 260084mS CMTARGET: (null): ADD PRIMARY
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD VM TARGET: FAILED availability=2
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: CancelTimer CMTCDelayedProcessing
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: NO INITIAL TARGETS: ??
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Fallback() targeting failed
17:10:27 260085mS CMLOGGING: CALL:2015/09/0717:10,00:00:00,000,103,O,*17,*17,Lynn,,,1,,"",0,n/a
17:10:27 260085mS CD: CALL: 259.1003.0 BState=Idle Cut=0 Music=0.0 Aend="Lynn(103)" (0.0) Bend="" [] (0.0) CalledNum=*17 () CallingNum=103 (Lynn) Internal=1 Time=1303 AState=Dialling
17:10:27 260085mS CD: CALL: 259.1003.0 Deleted
17:10:27 260085mS CMExtnEvt: Lynn: CALL LOST (CMCauseNoChannel)
17:10:27 260085mS CMExtnEvt: Lynn: Extn(103) Calling Party Number(103) Type(CMNTypeInternal)
17:10:27 260085mS CMCallEvt: c0a80ac8000003eb 259.1003.0 -1 Lynn.0: StateChange: END=X CMCSDialling->CMCSCompletedTone
17:10:27 260086mS CMExtnEvt: v=3 State, new=CMESCompleted old=Dialling,0,0,Lynn
17:10:27 260086mS CMCallEvt: 0000000000000000 0.1004.0 -1 BaseEP: DELETE CMEndpoint f1919a68 TOTAL NOW=1 CALL_LIST=0
17:10:27 260086mS CMCallEvt: END CALL:1 (f191bc9c)
17:10:27 260088mS CMMap: PCG::AddToneGenerator g B2[5] for cp[57]b0r1 append pcp[58]b0r1 (total 1)
17:10:27 260088mS CMMap: PlatformConnectionAudioSAP::Bind pcp[58]b0r1 to 0.0
17:10:27 260089mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[58]b0r1 Configure 0.0
17:10:27 260089mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[58]b0r1 ConnectIndication 0.0
17:10:27 260089mS CMMap: a=0.0 b=0.0 pcp[57]b0r1 RTPB2
17:10:27 260089mS H323Evt: SESS 1 SetOperational local 192.168.10.200:49152 remote 192.168.2.5:52644 to 1
17:10:28 261124mS H323Evt: SESS 1: RTP(50r): 192.168.10.200/49152 192.168.2.5/52644 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=2009 SENT=52 (avg size=164) RECV=50 (avg size=160)
17:10:32 265616mS RES: Mon 7/9/2015 17:10:32 FreeMem=60148000 (Heap=59982140(0) + Cache=165860) MemObjs=6391(Max 6693) CMMsg=5(5) Buff=5200 1364 1000 7460 5 Links=51824(58000) BTree=14523 CPU=02.16% CPUStats=04.69%/1/2/30534/34269/36413/00.37%/1/01.9
0% MCR=0 MCW=0
17:10:32 265616mS RES2: IP 500 V2 9.1.2.0 build 91 Tasks=43 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=59 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=0 TCP=23(TLS=6) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
17:10:32 265616mS RES4: XML MemObjs=63 PoolMem=4876404(2) FreeMem=4861100(0)
17:10:32 265616mS RES5: CLog MemObjs=215 FreePoolMem(Objs)=4420(85) TotalMem=119200
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[] Type=Default (100) Reason=CMDRdirect Calling[103] Type=Internal Plan=Default
BC: CMTC=Speech CMTM=Circuit CMTR=64 CMST=Default CMU1=ULaw
IE CMIEFastStartInfoData (6) 12 item(s)
IE CMIECallingPartyName (110)(Type=CMNameDefault) name=Lynn
IE CMIECallingPartyKName (226)(Type=CMNameDefault) name=Lynn
17:10:26 259105mS CMCallEvt: c0a80ac8000003eb 259.1003.0 1 Lynn.0: StateChange: END=A CMCSIdle->CMCSDialInitiated
17:10:26 259105mS CMExtnEvt: v=3 State, new=Dialling old=Idle,0,0,Lynn
17:10:26 259106mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party= sub= calling=103 dir=out complete=0 ses=0
17:10:26 259106mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number= type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:26 259106mS CMCallEvt: c0a80ac8000003eb 259.1003.0 1 Lynn.0: StateChange: END=A CMCSDialInitiated->CMCSDialling
17:10:26 259109mS CMExtnTx: v=103, p1=0
CMFacility
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
IE CMIEFastStartInfoData (6) 2 item(s)
IE CMIESecurityData (253) 2 item(s)
CMSecurityElement RX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
CMSecurityElement TX_ONLY {
CMSRTPCryptoCapability none
Codecs list (size 4)
}
Timed: 07/09/15 17:10
17:10:26 259109mS H323Evt: PortmAvayaH323Phone:
17:10:26 259109mS CMExtnTx: v=103, p1=8008
CMFacility
Line: type=IPLine 250 Call: lid=259 id=3 in=1
IE CMIEFastStartInfoData (6) 2 item(s)
17:10:26 259110mS CMExtnTx: v=103, p1=0
CMSetupAck
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Timed: 07/09/15 17:10
17:10:26 259110mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[*] Type=Default (100) Reason=CMDRdirect Keypad[*]
17:10:26 259110mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:26 259111mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=* sub= calling=103 dir=out complete=0 ses=0
17:10:26 259111mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=* type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:26 259114mS CD: CALL: 259.1003.0 BState=Idle Cut=0 Music=0.0 Aend="Lynn(103)" (0.0) Bend="" [] (0.0) CalledNum=* () CallingNum=103 (Lynn) Internal=1 Time=331 AState=Dialling
17:10:26 259115mS H323Evt: SESS 1 SetOperational local 192.168.10.200:0 remote 0.0.0.0:0 to 0
17:10:26 259116mS H323Evt: SESS 1 SetRemUDP 0 -> 52644
17:10:26 259506mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,103: Digit Key Pressed 1
17:10:26 259506mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[1] Type=Default (100) Reason=CMDRdirect Keypad[1]
17:10:26 259506mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:26 259507mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=*1 sub= calling=103 dir=out complete=0 ses=0
17:10:26 259507mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=*1 type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:27 260081mS CMExtnEvt: v=(null) State, new=Idle old=Idle,0,0,103: Digit Key Pressed 7
17:10:27 260081mS CMExtnRx: v=103, p1=0
CMInformation
Line: type=IPLine 250 Call: lid=259 id=1003 in=0
Called[7] Type=Default (100) Reason=CMDRdirect Keypad[7]
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Setting Hard Timer 3000
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: LOOKUP CALL ROUTE: GID=0 type=100 called_party=*17 sub= calling=103 dir=out complete=0 ses=0
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD TARGET (N): number=*17 type=100 depth=1 nobar=1 setorig=1 ses=0
17:10:27 260082mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: SYS SC: *17 3 sc=type=VoicemailCollect code=*17, num=?U callinfop->sending_complete=0 secondary_dialtone=
17:10:27 260083mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD VM TARGET
17:10:27 260083mS CMTARGET: **** c0a80ac8000003eb 259.1003.0 1 Lynn.0: MakeVoicemailTarget pbx=<null> local=1 type=3
17:10:27 260083mS CMMap: Mapper::AllocateCodec unable to allocate resource
17:10:27 260083mS CMCallEvt: Cannot reserve a codec for Aend, aend is c0a80ac8000003eb 259.1003.0 1 Lynn.0
17:10:27 260084mS CMTARGET: (null): ADD PRIMARY
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: ADD VM TARGET: FAILED availability=2
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: CancelTimer CMTCDelayedProcessing
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: NO INITIAL TARGETS: ??
17:10:27 260084mS CMTARGET: c0a80ac8000003eb 259.1003.0 1 Lynn.0: Fallback() targeting failed
17:10:27 260085mS CMLOGGING: CALL:2015/09/0717:10,00:00:00,000,103,O,*17,*17,Lynn,,,1,,"",0,n/a
17:10:27 260085mS CD: CALL: 259.1003.0 BState=Idle Cut=0 Music=0.0 Aend="Lynn(103)" (0.0) Bend="" [] (0.0) CalledNum=*17 () CallingNum=103 (Lynn) Internal=1 Time=1303 AState=Dialling
17:10:27 260085mS CD: CALL: 259.1003.0 Deleted
17:10:27 260085mS CMExtnEvt: Lynn: CALL LOST (CMCauseNoChannel)
17:10:27 260085mS CMExtnEvt: Lynn: Extn(103) Calling Party Number(103) Type(CMNTypeInternal)
17:10:27 260085mS CMCallEvt: c0a80ac8000003eb 259.1003.0 -1 Lynn.0: StateChange: END=X CMCSDialling->CMCSCompletedTone
17:10:27 260086mS CMExtnEvt: v=3 State, new=CMESCompleted old=Dialling,0,0,Lynn
17:10:27 260086mS CMCallEvt: 0000000000000000 0.1004.0 -1 BaseEP: DELETE CMEndpoint f1919a68 TOTAL NOW=1 CALL_LIST=0
17:10:27 260086mS CMCallEvt: END CALL:1 (f191bc9c)
17:10:27 260088mS CMMap: PCG::AddToneGenerator g B2[5] for cp[57]b0r1 append pcp[58]b0r1 (total 1)
17:10:27 260088mS CMMap: PlatformConnectionAudioSAP::Bind pcp[58]b0r1 to 0.0
17:10:27 260089mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[58]b0r1 Configure 0.0
17:10:27 260089mS CMMap: PlatformConnectionAudioSAP::ConnectVoice pcp[58]b0r1 ConnectIndication 0.0
17:10:27 260089mS CMMap: a=0.0 b=0.0 pcp[57]b0r1 RTPB2
17:10:27 260089mS H323Evt: SESS 1 SetOperational local 192.168.10.200:49152 remote 192.168.2.5:52644 to 1
17:10:28 261124mS H323Evt: SESS 1: RTP(50r): 192.168.10.200/49152 192.168.2.5/52644 CODEC=Ulaw64K(5) PKTSZ=160 RFC2833=off AGE=2009 SENT=52 (avg size=164) RECV=50 (avg size=160)
17:10:32 265616mS RES: Mon 7/9/2015 17:10:32 FreeMem=60148000 (Heap=59982140(0) + Cache=165860) MemObjs=6391(Max 6693) CMMsg=5(5) Buff=5200 1364 1000 7460 5 Links=51824(58000) BTree=14523 CPU=02.16% CPUStats=04.69%/1/2/30534/34269/36413/00.37%/1/01.9
0% MCR=0 MCW=0
17:10:32 265616mS RES2: IP 500 V2 9.1.2.0 build 91 Tasks=43 RTEngine=0 CMRTEngine=0 ExRTEngine=0 Timer=59 Poll=0 Ready=0 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1 SSA=0 TCP=23(TLS=6) TAPI=0 ASC=1 SYS=MNTD OPT=UMNT SDSPD=2034
17:10:32 265616mS RES4: XML MemObjs=63 PoolMem=4876404(2) FreeMem=4861100(0)
17:10:32 265616mS RES5: CLog MemObjs=215 FreePoolMem(Objs)=4420(85) TotalMem=119200