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?

 

[jreingold]

We monitor the service, and for that monitor event log entries on all our voicemail pro servers.

The problem is that with this bug, the voicemail pro service DOES NOT CRASH. It does not stop, and it does not log any errors in the event log. The service is still running. It just plays dead air.

-Jeff

 

[h382]

Exactly what jreingold said.

 

[tlpeter]

That is a big problem then
The only thing you can do is report this problem with avaya


ACA - Implement IP Office
ACS - 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]

I believe jreingold has a ticket with avaya open on this, and to this point they can't figure it out either.. I haven't had to open a ticket since I stopped working for a distributor and that was almost a year ago.. But.. I may have met my match on this one.

 

[h382]

Alright.. Issue happened again this morning.. This is what happened in the Voicemail logging window.. It looks like it allowed Chris to get his messages, but 5 minutes later VM went to dead air.

BTW. I replaced the name and phone #'s in this log..

07:06:49.875 - New VMAIL Client
07:06:49.906 - Session: 00000654 - Configuring for reliable disconnect, IDLE time is 300.000s
07:06:49.906 - Session: 00000654 - Receive OPEN for session 00000654, call-id 6192
07:06:49.906 - Session: 00000654 - Check flags[13] 0 for advising recording
07:06:49.906 - Session: 00000654 - Receive OPEN for session 00000654, call-id 6192
07:06:49.906 - Session: 00000654 - Access = ACCESS_RETRIEVE_VOICEMAIL:
07:06:49.906 - Session: 00000654 - Mailbox:
07:06:49.906 - Session: 00000654 - Calling Party: 7045555555
07:06:49.922 - Session: 00000654 - Display String: 7045555555>?
07:06:49.922 - Session: 00000654 - Target Party:
07:06:49.922 - Session: 00000654 - Greeting Modifier:
07:06:49.922 - Session: 00000654 - Language: enu
07:06:49.922 - Session: 00000654 - Call Ident: 6192
07:06:49.922 - Session: 00000654 - Call Status: Unknown (0)
07:06:49.922 - Session: 00000654 - Call Type: External
07:06:49.938 - Session: 00000654 - Call Direction: Incoming
07:06:49.938 - Session: 00000654 - Called Party:
07:06:49.938 - Session: 00000654 - DDI Number: 1960
07:06:49.938 - Session: 00000654 - Calling Party Name:
07:06:49.938 - Session: 00000654 - Called Party Name:
07:06:49.938 - Session: 00000654 - FindMailBoxByCLI 7045555555
07:06:49.953 - Session: 00000654 - - Internal: !Internal!=N
07:06:49.969 - Session: 00000654 - Configuring for reliable disconnect, IDLE time is 300.000s
07:06:49.969 - Session: 00000654 - Receive ACTIVE for session 00000654, call-id 6192
07:07:06.651 - Session: 00000654 - Summary mailbox=(Chris Farley), (3,18,0)
07:07:12.008 - Session: 00000654 - FindMailBoxByCLI 4155474400
07:07:12.008 - Session: 00000654 - IntuityReceiveMenu: Message MSG02257 left DOW=5,07/03/2008 11:19:12 from 4155474400[4155474400>Chris Farley], 39.744 secs
07:07:13.058 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02257.WAV, maximum energy was 112.221947, factor used to normalize 0.374055, took 126 ms
07:07:13.089 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02257.WAV, rewritten at 0.180000 FS
07:07:13.089 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02257$O$2008/3/7 11:19$4155474400$39$0$0$1901$%
07:07:25.119 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02257$O$2008/3/7 11:19$4155474400$39$0$0$1901$%
07:07:25.119 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02257$D$2008/3/7 11:19$4155474400$39$0$0$1901$%
07:07:26.169 - Session: 00000654 - FindMailBoxByCLI 4154020096
07:07:26.169 - Session: 00000654 - IntuityReceiveMenu: Message MSG02258 left DOW=5,07/03/2008 13:53:08 from 4154020096[4154020096>Main], 18.389 secs
07:07:33.327 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02258.WAV, maximum energy was 40.474946, factor used to normalize 0.622847, took 47 ms
07:07:33.327 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02258.WAV, rewritten at 0.180000 FS
07:07:33.374 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02258$O$2008/3/7 13:53$4154020096$18$0$0$1901$%
07:07:51.983 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02258$O$2008/3/7 13:53$4154020096$18$0$0$1901$%
07:07:51.983 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02258$D$2008/3/7 13:53$4154020096$18$0$0$1901$%
07:07:53.032 - Session: 00000654 - FindMailBoxByCLI 4153437916
07:07:53.032 - Session: 00000654 - IntuityReceiveMenu: Message MSG02259 left DOW=5,07/03/2008 14:24:39 from 4153437916[4153437916>Chris Farley], 43.516 secs
07:08:00.253 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02259.WAV, maximum energy was 12.178114, factor used to normalize 1.135493, took 109 ms
07:08:00.285 - Session: 00000654 - Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Accounts\Chris Farley\MSG02259.WAV, rewritten at 0.180000 FS
07:08:00.300 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02259$O$2008/3/7 14:24$4153437916$43$0$0$1901$%
07:08:23.734 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02259$O$2008/3/7 14:24$4153437916$43$0$0$1901$%
07:08:23.734 - Session: 00000654 - Notify Message to Phone Manger 1901 VMM$MSG02259$D$2008/3/7 14:24$4153437916$43$0$0$1901$%
07:08:24.799 - Session: 00000654 - FindMailBoxByCLI 4153789360
07:08:24.799 - Session: 00000654 - IntuityReceiveMenu: Message MSG02150 left DOW=1,11/02/2008 07:21:06 from 4153789360[4153789360>Chris Farley], 120.143 secs
07:08:28.308 - Session: 00000654 - Receive CLOSE for session 00000654, call-id 0
07:08:28.339 - Session: 00000654 - Mailbox name retrieved=Chris Farley new=0 unopened=0 old=18 saved=0
07:08:28.339 - ~IClient [Connections 0 - 0] [Buffer pool(0:1000 1:250 2:250 3:548), in use:0] [Links:11189 from 12000] [CMMsg:1 left from 1] [VM:0 NODES:0 SN:0 SBL:0 TASKS:5 FILES:0 Msgs:476]
07:13:12.796 - No response from PBX 10.50.45.41, removing from list
07:13:12.796 - 68 mailboxes were open (but not active) when flushed
07:13:12.874 - DevIO::RxAbort 10.50.45.41
07:13:12.874 - DevIO:etach 10.50.45.41
07:13:15.945 - Create New User 10.50.45.41 port=4759

07:13:15.976 - Response for WhoIs2 from 10.50.45.41 is
mac="00e00703035f" type="IP 406 DS" class="CPU" icon="0" ver="4.1 (95011)" name="SFOIP406v2"
state="3"
base port"=50804"

07:13:15.976 - Licence Summary for 10.50.45.41
07:13:15.976 - Voicemail Pro is licenced
07:13:15.976 - Integrated messaging is NOT licenced
07:13:15.976 - 3rd Party License is NOT licenced
07:13:15.976 - VPIM is NOT licenced
07:13:15.976 - Voice recording library is NOT licenced
07:13:15.991 - 3rd Party Database is NOT licenced
07:13:15.991 - VB Scripting is NOT licenced
07:13:15.991 - Outlook Calendar based greetings is NOT licenced
07:13:15.991 - ScanSoft TTS Support is NOT licenced
07:13:15.991 - Generic TTS Support is NOT licenced
07:48:42.032 - House keeping started...
07:48:42.032 - VRL HouseKeeping Finished...
07:48:42.032 - House keeping complete
09:48:42.455 - House keeping started...
09:48:42.455 - VRL HouseKeeping Finished...
09:48:42.455 - House keeping complete
11:48:56.031 - House keeping started...
11:48:56.031 - VRL HouseKeeping Finished...
11:48:56.031 - House keeping complete

As of posting this message it is still dead air, I have not restarted the services yet. But, as you can see above, it says it's licensed.

 

[h382]

This what the DbgView says

08/03 07:13:53.304 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 07:13:53.304 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 07:13:53.304 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 07:13:12.796 vmprov5s (09,5) 772,3900: 68 mailboxes were open (but not active) when flushed
08/03 07:13:12.874 vmprov5s (09,5) 772,3900: DevIO::RxAbort 10.50.45.41
08/03 07:13:12.874 vmprov5s (09,5) 772,3900: DevIO:etach 10.50.45.41
08/03 07:13:12.921 DbgOut (01,5) 772, 576: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 07:13:12.952 DbgOut (01,5) 772,2772: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 07:13:15.945 vmprov5s (09,5) 772,1400: Create New User 10.50.45.41 port=4759
08/03 07:13:15.976 vmprov5s (09,5) 772,1400: Response for WhoIs2 from 10.50.45.41 is
mac="00e00703035f" type="IP 406 DS" class="CPU" icon="0" ver="4.1 (95011)" name="SFOIP406v2"
state="3"
base port"=50804"
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: Licence Summary for 10.50.45.41
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: Voicemail Pro is licenced
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: Integrated messaging is NOT licenced
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: 3rd Party License is NOT licenced
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: VPIM is NOT licenced
08/03 07:13:15.976 vmprov5s (09,3) 772,1400: Voice recording library is NOT licenced
08/03 07:13:15.991 vmprov5s (09,3) 772,1400: 3rd Party Database is NOT licenced
08/03 07:13:15.991 vmprov5s (09,3) 772,1400: VB Scripting is NOT licenced
08/03 07:13:15.991 vmprov5s (09,3) 772,1400: Outlook Calendar based greetings is NOT licenced
08/03 07:13:15.991 vmprov5s (09,3) 772,1400: ScanSoft TTS Support is NOT licenced
08/03 07:13:15.991 vmprov5s (09,3) 772,1400: Generic TTS Support is NOT licenced
08/03 07:13:20.995 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 07:13:20.995 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 07:13:20.995 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 07:13:35.957 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 07:13:35.957 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 07:13:35.957 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 07:13:50.920 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 07:13:50.920 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 07:13:50.920 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 07:14:05.882 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 07:14:05.882 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 07:14:05.882 KeyServ (01,5) 380, 464: lR: 4027407 status: 0

 

[h382]

When I restart the service.. This is what I get..

I know it's a lot of info.. But, I'm trying to capture everything I can.

08/03 12:39:47.909 DbgOut (01,5) 2676,2748: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 12:39:48.705 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 12:39:48.705 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 12:39:48.705 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 12:39:50.580 DbgOut (00,5) 1172,1504: Process file is 'C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\vmprov5svc.exe' and DLL file is 'C:\WINDOWS\system32\DbgOut.Dll'
08/03 12:39:50.580 vmprov5s (0b,5) 1172,1504: VMRegistry - registry opened with full access
08/03 12:39:50.611 DbgOut (01,5) 1172,2360: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:50.658 DbgOut (01,5) 1172, 612: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:50.658 DbgOut (01,5) 1172,1732: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:50.720 DbgOut (01,5) 1172,3244: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:50.752 DbgOut (01,5) 1172,1384: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:50.892 DbgOut (01,5) 1172,4052: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:51.533 DbgOut (01,5) 1172,1548: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:51.751 vmprov5s (0c,2) 1172,2360: > SoundsManager::NormalizeWAV(ALAW (18%) file:C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV)
08/03 12:39:51.767 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, maximum energy was 25.827310, factor used to normalize 0.779714, took 0 ms
08/03 12:39:51.767 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, rewritten at 0.180000 FS
08/03 12:39:51.767 vmprov5s (0c,2) 1172,2360: < SoundsManager::NormalizeWAV()
08/03 12:39:51.830 vmprov5s (0c,2) 1172,2360: > SoundsManager::NormalizeWAV(ALAW (18%) file:C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV)
08/03 12:39:51.830 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, maximum energy was 24.604133, factor used to normalize 0.798860, took 0 ms
08/03 12:39:51.830 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, rewritten at 0.180000 FS
08/03 12:39:51.830 vmprov5s (0c,2) 1172,2360: < SoundsManager::NormalizeWAV()
08/03 12:39:51.830 DbgOut (01,5) 1172,1548: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 12:39:51.876 DbgOut (01,5) 1172,1500: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:51.908 vmprov5s (0c,2) 1172,2360: > SoundsManager::NormalizeWAV(ALAW (18%) file:C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV)
08/03 12:39:51.908 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, maximum energy was 25.827310, factor used to normalize 0.779714, took 0 ms
08/03 12:39:51.908 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, rewritten at 0.180000 FS
08/03 12:39:51.908 vmprov5s (0c,2) 1172,2360: < SoundsManager::NormalizeWAV()
08/03 12:39:51.923 vmprov5s (0c,2) 1172,2360: > SoundsManager::NormalizeWAV(ALAW (18%) file:C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV)
08/03 12:39:51.923 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, maximum energy was 24.604133, factor used to normalize 0.798860, took 0 ms
08/03 12:39:51.923 vmprov5s (09,3) 1172,2360: Wave file C:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\TTSMSG00.WAV, rewritten at 0.180000 FS
08/03 12:39:51.923 vmprov5s (0c,2) 1172,2360: < SoundsManager::NormalizeWAV()
08/03 12:39:51.939 DbgOut (01,5) 1172,1500: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 12:39:52.033 DbgOut (01,5) 1172, 228: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:52.611 vmprov5s (09,3) 1172,2360: Database Pool Initialised
08/03 12:39:52.658 vmprov5s (09,5) 1172,2360: Loading VMP configuration...
08/03 12:39:52.751 vmprov5s (09,5) 1172,2360: No IVR Node for Remote call flow modules
08/03 12:39:52.751 vmprov5s (09,5) 1172,2360: Processing Campaigns...
08/03 12:39:52.751 DbgOut (01,5) 1172,4088: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:52.970 vmprov5s (09,5) 1172,2360: Using mask of 255.255.255.255
08/03 12:39:52.986 vmprov5s (09,5) 1172,2360: Failed to connect to database
08/03 12:39:52.986 vmprov5s (09,5) 1172,2360: Failed to load SIP support
08/03 12:39:52.986 vmprov5s (09,3) 1172,2360: Socket bind failed port=37 error=2740
08/03 12:39:52.986 DbgOut (01,5) 1172,3060: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:52.986 DbgOut (01,5) 1172,2952: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:53.204 DbgOut (01,5) 1172,3396: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:53.204 DbgOut (01,5) 1172,1212: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:53.204 DbgOut (01,5) 1172,3684: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:39:53.204 vmprov5s (00,2) 1172,3396: SessionManager::VPIMThreadRoutine - Error 0x79e71ad0 connecting to VPIM Database Server
08/03 12:39:53.220 DbgOut (01,5) 1172,3396: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 12:39:53.220 DbgOut (01,5) 1172,1212: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_DETACH)
08/03 12:40:03.702 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 12:40:03.702 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 12:40:03.702 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 12:40:14.059 vmprov5s (09,5) 1172,4088: Create New User 10.50.45.41 port=4759
08/03 12:40:14.075 vmprov5s (09,5) 1172,4088: Response for WhoIs2 from 10.50.45.41 is
mac="00e00703035f" type="IP 406 DS" class="CPU" icon="0" ver="4.1 (95011)" name="SFOIP406v2"
state="3"
base port"=50804"
08/03 12:40:14.091 vmprov5s (09,3) 1172,4088: Licence Summary for 10.50.45.41
08/03 12:40:14.091 vmprov5s (09,3) 1172,4088: Voicemail Pro is licenced
08/03 12:40:14.091 vmprov5s (09,3) 1172,4088: Integrated messaging is NOT licenced
08/03 12:40:14.091 vmprov5s (09,3) 1172,4088: 3rd Party License is NOT licenced
08/03 12:40:14.106 vmprov5s (09,3) 1172,4088: VPIM is NOT licenced
08/03 12:40:14.106 vmprov5s (09,3) 1172,4088: Voice recording library is NOT licenced
08/03 12:40:14.106 vmprov5s (09,3) 1172,4088: 3rd Party Database is NOT licenced
08/03 12:40:14.106 vmprov5s (09,3) 1172,4088: VB Scripting is NOT licenced
08/03 12:40:14.122 vmprov5s (09,3) 1172,4088: Outlook Calendar based greetings is NOT licenced
08/03 12:40:14.122 vmprov5s (09,3) 1172,4088: ScanSoft TTS Support is NOT licenced
08/03 12:40:14.122 vmprov5s (09,3) 1172,4088: Generic TTS Support is NOT licenced
08/03 12:40:14.122 vmprov5s (09,5) 1172,4088: BulkInfoRequest 10.50.45.41 2
08/03 12:40:14.122 vmprov5s (09,5) 1172,4088: PBX Requesting ULaw companding
08/03 12:40:14.138 vmprov5s (09,5) 1172,4088: Initialize Sequencer tx_seq=0, rx_seq=0
08/03 12:40:14.138 DbgOut (01,5) 1172, 192: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:40:14.138 vmprov5s (09,5) 1172,4088: TFTPLoadFile 10.50.45.41
08/03 12:40:14.138 vmprov5s (09,5) 1172,4088: 0 mailboxes were open (but not active) when flushed
08/03 12:40:14.153 DbgOut (01,5) 1172, 680: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:40:14.153 vmprov5s (09,5) 1172,4088: DevIO::StartTask 10.50.45.41
08/03 12:40:14.684 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.684 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.700 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.700 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.716 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.716 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.731 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.731 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.747 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.762 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.778 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.778 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.794 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.794 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.840 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.840 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.856 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.856 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.872 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.872 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.887 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.887 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.903 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.903 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.919 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.919 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.934 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.934 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.950 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.950 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.965 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.965 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.981 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.981 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:14.997 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:14.997 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.012 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.012 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.028 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.028 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.044 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.044 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.059 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.059 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.075 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.075 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.090 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.090 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.106 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.106 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.122 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.122 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.137 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.137 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.153 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.153 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.169 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.169 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.184 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.184 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.200 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.200 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.215 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.215 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.231 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.231 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.247 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.262 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.278 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.278 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.294 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.294 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.309 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.309 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.325 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.325 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.340 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.340 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.356 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.356 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.372 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.372 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.387 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.387 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.403 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.403 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.418 vmprov5s (09,5) 1172, 680: DevIO:rocessReceiveBuffer 10.50.45.41
08/03 12:40:15.418 vmprov5s (09,5) 1172, 680: DevIO::RxData 10.50.45.41
08/03 12:40:15.418 vmprov5s (09,5) 1172, 680: DevIO::RxComplete 10.50.45.41
08/03 12:40:15.434 vmprov5s (0a,3) 1172, 680: Control Unit or app has not specified config version - defaulting to latest release (4.0.0)
08/03 12:40:15.450 vmprov5s (09,5) 1172, 680: 0 mailboxes were open (but not active) when flushed
08/03 12:40:18.699 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 12:40:18.699 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 12:40:18.699 KeyServ (01,5) 380, 464: lR: 4027407 status: 0
08/03 12:40:20.652 DbgOut (01,5) 1172,3380: DllMain(hinstDLL=0x10000000, fdwReason=DLL_THREAD_ATTACH)
08/03 12:40:20.949 vmprov5s (09,5) 1172, 680: SendBulkInfo 10.50.45.41
08/03 12:40:20.949 vmprov5s (09,5) 1172, 680: BulkInfo Response 50 10.50.45.41
08/03 12:40:20.949 vmprov5s (09,5) 1172, 680: BulkInfo Response 18 10.50.45.41
08/03 12:40:20.949 vmprov5s (09,3) 1172, 680: Updating campaign park slot information
08/03 12:40:33.696 KeyServ (01,5) 380, 464: HiWord: 61 status: 0
08/03 12:40:33.696 KeyServ (01,5) 380, 464: LoWord: 29711 status: 0
08/03 12:40:33.696 KeyServ (01,5) 380, 464: lR: 4027407 status: 0

So... now it works... for the time being..

 

[ronromano]

The very first IPO I put in worked great for about 6 months, then we started to get a problem very similar to this. After banging my head against the wall for about 8 hours, and having asked the customer once if any new DHCP servers had been intoduced and told no, it turned out be he had put in a small router that had DHCP on and it was giving out the IP address of the IPO.

Please check and make sure nothing like that in in your situation. IP address conficts wreak havok with the IPO to VM connection.

 

[jreingold]

I agree, but in the two identical cases like this that we have, it is not an ip conflict. It is an obvious bug introduced in 4.1 (one was an upgrade from 3.2, the other was a fresh 4.1 install) where randomly the IPO and vm pro svc start to exerience one-way communication. IPO is transmitting to VM, and even though VM is running, IPO receives no packets back.

My debug traces look very similar to above, and several have been submitted to Avaya L4...

-Jeff

 

[h382]

I decided to go into the BootP entries, and delete the previous entry that was in there for the old 403. It had it listed with the same IP Address, but a different MAC address.. I have never seen this cause an issue before, but something made me want to delete it. The only BOOTP entry now is the one for this 406v2.

I'll keep everyone posted.

 

[Westi]

just something that came into my mind, I had a 403 that had similar symptoms but with losing the licenses and then stopping, I did a terminal ping to the IPO control unit and let that run for about 2 minutes and it timed out intermittendly although the pc was connected directly to the LAN ports on the 403. This also happened when no customer network was present and it was faulty hardware, the 403 needed to get replaced and it is running for 2 years now without problems. Try it and maybe you get lucky and it is as simple as the IPO really not responding.
good luck

Joe W.

FHandw.
ACA
ACS

 

[h382]

I will do a ping trace and see if there is a loss in connection.

 

[jreingold]

We have continous connectivity from the IP Office to the Voicemail Pro servers with no dropped packets. SysMon debugs running at all times on voicemail servers collecting data from the IPO, without skipping a beat, no problem loading live config from IPO in manager from the voicemail server, we monitor the 406 and 500 and voicemail servers with pings and event log montiors, wmi, etc. 24x7 and have no network connectivity problems.

While many of these suggestions are very plausible in many similar situations, there is no doubt in my mind that in my two specific cases and it sure sounds like in h382's, we are all seeing the same exact VM Pro bug.

-Jeff

 

[h382]

Jeff

Did you say you had a ticket with Avaya open on this? Have they shed any light on this situation?

 

[jreingold]

I have a tkt open for 2 weeks now, sent countless traces, had l3 remote into the box, and keeps sending l4 the traces. Gave me a private build which didn't fix it but has greater debugging built into it...Last sent traces Wednesday, and left many voicemails and emails for a status Thursday and Friday with no response yet.

I don't know who is more frustrated - me or the two customers...

-Jeff

 

[h382]

You can let them know there is someone else having the same issue. If they need to talk to me, I have no problem with that. I used to talk to them all the time when I worked for a Distributor.. Haven't talked to them in about a year though.

 

[Duffman88]

You guys have any luck with Avaya? I am having the same exact problem. My timeframe seems to be a little longer though. Problem happens every week or every couple of weeks which makes it very hard to troubleshoot. I'll post some logs a little bit later.

Whatever happened to the days of stuff just breaking. So much easier to fix when it just doesnt work at all. Intermittent problems drive me insane.

~Chris
ACA

 

[h382]

I haven't had any luck yet. I am debating on replacing the 406v2 as it is still under warranty. I have to fly across country to do this, so I'm not exactly excited about a "shot in the dark" fix.

My issue seems to happening only 2-3 times a week now. But, the customer is getting extremely impatient with this.

 

[h382]

Actually.. I may just bring them back to 3.2

They were on 3.0 with a 403 previously and didn't have any issues. The VM Server is the same as it was before as is everything else. IP's, ports, Users, applications, etc are all the same as they were with the 403, and never had an issue. The only 2 things that changed was putting in the 406v2, and using version 4.+

 

[Duffman88]

I have had a number of problems with the 4.+ software. Most of which were fixed with T3 patches then they posted the GA release. You had no problems with this until you updated the IPO software?

What IPO and VMPro version were you running before you had problems? Or did this happen almost immediately after upgrading to the 406v2? I am running 4.1.9 and 4.1.27 vmpro. I am wondering if its the VMPro or the IPO causing the problem.

-Chris
ACA