IP Office disconnects on Voicemail Pro transfer

[zachlac]

We're trying to use Voicemail Pro Autoattendant to handle incoming calls. However, whenever an external call comes in and the person types an extension to transfer to, the call is disconnected. I've collected a log from DbgView, shown at the bottom. You can see where, near the end of the call, the session simply receives a CLOSE for no reason.

Why is this automatically disconnecting?

22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   New VMAIL Client
22/02 15:46:41.640 DbgOut   (01,5) 1340,3732: DllMain(hinstDLL=0x10000000,
fdwReason=DLL_THREAD_ATTACH)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Configuring for reliable
disconnect, IDLE time is 300.000s
22/02 15:46:41.640 vmprov5s (06,5) 1340,1464:   VMClient::RxOpen 04F4855C
Short Codes.autoattend (4), session=0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Receive OPEN  for session
104, call-id 24
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Access =
ACCESS_UNCLUED_VOICEMAIL:
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Mailbox: Short
Codes.autoattend
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Calling Party: 910008
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Display String: 910008
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Called Party:
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Greeting Modifier:
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Language: enu
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Call Ident: 24
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Call Status: Unknown (0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Call Type: External
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Call Direction: Incoming
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:       Call Type: External
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   FindMailBoxByCLI 910008
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   FindMailBoxByCLI 910008
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Found VMPNode Short
Codes.autoattend
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   FindMailBoxByCLI 910008
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Short Codes.autoattend.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Short
Codes.autoattend.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Short Codes.autoattend.Test Conditions.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Short
Codes.autoattend.Test Conditions.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Short Codes.autoattend.Test Conditions.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Short
Codes.autoattend.Test Conditions.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Weather Condition.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Weather Condition.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Weather Condition.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Weather Condition.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Comparison ' == closed' 
Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Holiday.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Holiday.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Holiday.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Holiday.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '04/07/2006
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '23/11/2006
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '25/12/2006
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '01/01/2007
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '04/07/2007
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '22/11/2007
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '25/12/2007
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '01/01/2008
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '10/10/2006
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '17/10/2006
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Date Compare '23/11/2007
vs (null)'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Tested Condition
'HolidayCalendar'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Day Night.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Day Night.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Test Day Night.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Test Day Night.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Day Compare '2'  Result: 1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Time Compare '09:00 vs
18:00'  Result: 1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Day Compare '3'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Day Compare '4'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Day Compare '5'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Day Compare '6'  Result: 0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Tested Condition
'WeeklyBusinessSchedule'  Result: 1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Open for Business.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Open for Business.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Test Conditions.Open for Business.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Test
Conditions.Open for Business.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Short Codes.autoattend.Day Menu.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Short
Codes.autoattend.Day Menu.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Short Codes.autoattend.Day Menu.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Short
Codes.autoattend.Day Menu.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Day Menu
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Day Menu
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Day Menu.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Day
Menu.Start Point.1
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing request to run
node Day Menu.Day Menu.0
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:   Executing node Day
Menu.Day Menu.0
22/02 15:46:41.640 vmprov5s (06,5) 1340,1464:   VMClient::RxOpen - Created
dialog 03B3C1F4
22/02 15:46:41.640 vmprov5s (09,5) 1340,1464:    - Internal: !Internal!=N
22/02 15:46:41.687 vmprov5s (09,5) 1340,1464:   Configuring for reliable
disconnect, IDLE time is 300.000s
22/02 15:46:41.687 vmprov5s (06,5) 1340,1464:   VMClient::RxActive
04F4855C (session=104)
22/02 15:46:41.687 vmprov5s (09,5) 1340,1464:   Receive ACTIVE  for
session 104, call-id 24
22/02 15:46:43.437 vmprov5s (1b,5) 1340,1464:   VMClient::DtmfDetect
04F4855C '2' at 520, length 240 - session:104
22/02 15:46:43.687 vmprov5s (1b,5) 1340,1464:   VMClient::DtmfDetect
04F4855C '3' at 400, length 240 - session:104
22/02 15:46:43.812 vmprov5s (1b,5) 1340,1464:   VMClient::DtmfDetect
04F4855C '4' at 1000, length 240 - session:104
22/02 15:46:43.812 vmprov5s (09,5) 1340,1464:   Executing request to run
node Day Menu.Transfer to Extension.0
22/02 15:46:43.812 vmprov5s (09,5) 1340,1464:   Executing node Day
Menu.Transfer to Extension.0
22/02 15:46:43.812 vmprov5s (09,5) 1340,1464:   Executing request to run
node Day Menu.Transfer to Extension.1
22/02 15:46:43.812 vmprov5s (09,5) 1340,1464:   Executing node Day
Menu.Transfer to Extension.1
22/02 15:46:45.453 vmprov5s (09,5) 1340,3732:   soundbites <= 0 so delete
sbl(0)
22/02 15:46:45.453 vmprov5s (09,5) 1340,3732:   SetTransfer=234
22/02 15:46:45.453 vmprov5s (09,5) 1340,3732:   GetTransfer=234
22/02 15:46:45.453 vmprov5s (06,5) 1340,3732:   VMClient::Transfer2
04F4855C 234 (session=104)
22/02 15:46:45.453 vmprov5s (09,5) 1340,3732:   SetTransfer=(null)
22/02 15:46:45.453 vmprov5s (06,5) 1340,1464:   VMClient::RxClose 04F4855C
(session=104)
22/02 15:46:45.453 vmprov5s (09,5) 1340,1464:   Receive CLOSE  for session
104, call-id 0
22/02 15:46:45.484 DbgOut   (01,5) 1340,3732: DllMain(hinstDLL=0x10000000,
fdwReason=DLL_THREAD_DETACH)

 

[CarGoSki]

Is 234 a extension with DND on and no vm coverage?

It's people like you who generalize.

 

[CarGoSki]

aka what happens when you dial 234 internally?

It's people like you who generalize.

 

[zachlac]

Internally, it rings through to the extension successfully. If I call the autoattendant internally using the short code, it can transfer me successfully. It is only on an external call coming in where the call is disconnected.

There is nothing on the DND list, and voicemail is on.

Thank you.

 

[CarGoSki]

Are you using assisted transfer and/or is the destination a ip extension?

It's people like you who generalize.

 

[zachlac]

I'm sorry, I'm not familiar enough with the system to answer that well, and unfortunately I did not set up the system. When I look at the short code entry, it transfers to a "Voicemail Node" with some number called "autoattend". The autoattend entry on Voicemail Pro eventually transfers to an extension. I'm not sure how to check if the extension is an IP extension. The device type is an Avaya 5410.

 

[CarGoSki]

Well a 5410 is a digital set and not an ip set. You are missing a lot of traces in dbgview but the menu to transfer is probably not built correctly >> Day Menu.Transfer to Extension.1 <<<

Your traces report that Autoattend checks to see if it is day or night and during the day transfers to Module Day>> Executing node Day <<

You could try navigating to Module/Day and snapping a screenie and posting here. You could also do file/save as in vmpro client and post the text. It will look something like this>>

; Auto-generated by IP Voicemail Pro Client
; For use with IP Office Voicemail Pro Server
; File produced on 05/10/2009 17:02:42
;
; DO NOT EDIT THIS FILE DIRECTLY
;

AttendatHours.Condition
{
MEMBERS OR
TIMEBAND MONDAY 08:00-16:00
MEMBERS OR
TIMEBAND TUESDAY 07:00-16:00
MEMBERS OR
TIMEBAND WEDNESDAY 07:00-16:00
MEMBERS OR
TIMEBAND THURSDAY 07:00-16:00
MEMBERS OR
TIMEBAND FRIDAY 07:00-16:00
MEMBERS OR
TIMEBAND SATURDAY 07:00-12:00
}

Holiday.Condition
{
MEMBERS OR
TIMEBAND 04/07/2007
TIMEBAND 04/07/2008
TIMEBAND 26/05/2008
TIMEBAND 01/09/2008
TIMEBAND 27/11/2008
TIMEBAND 25/12/2008
TIMEBAND 01/01/2009
TIMEBAND 25/05/2009
TIMEBAND 04/07/2009
TIMEBAND 07/09/2009
TIMEBAND 26/11/2009
TIMEBAND 25/12/2009
TIMEBAND 01/01/2010
}

Short Codes.direct
{
INTERRUPTABLE
ROOT
ACTION WAIT
EVENT RESULT.NODE_ENTRY=Short Codes.direct.Start Point.1
EVENT RESULT.Next=Short Codes.direct.Menu.0
}


etc..



It's people like you who generalize.

 

[zachlac]

I've saved a vmp file, but it's rather large, so I'll host it on box.net:

http://www.box.net/shared/yijxzpd41m

My screenshot is up on imgur:

http://imgur.com/cfNtp

I'm just curious: if the Day menu is incorrect, why would it correctly transfer internal calls?

I'll post just the day menu section below.

...
Short Codes.testaa.Day Menu.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Short Codes.testaa.Day Menu.1
}

Short Codes.testaa.Day Menu.1
{
    INTERRUPTABLE
    ACTION NODE=Day Menu
}
...
;
; ------------Callflow information for "Day Menu"------------
;


Day Menu
{
    INTERRUPTABLE
    ROOT
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Start Point.1
    EVENT RESULT.Next=Day Menu.Day Menu.0
}

Day Menu.Start Point.1
{
    INTERRUPTABLE
    ACTION NULL
    RESULT=Next
}

Day Menu.Day Menu.0
{
    MSG daymenu
    INTERRUPTABLE
    ACTION WAIT
    TIMEOUT 5=Day Menu.Transfer to Reception.0
    EVENT KEYSTR.0=Day Menu.Transfer to Reception.0
    EVENT KEYSTR.*=Day Menu.StarMenu.0
    EVENT KEYSTR.$=Day Menu.Invalid Option Return.0
    EVENT KEYSTR.2??=Day Menu.Transfer to Extension.0
    EVENT KEYSTR.5=Day Menu.Conf Bridge.0
}

Day Menu.Transfer to Reception.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Transfer to Reception.1
}

Day Menu.Transfer to Reception.1
{
    MSG yourebeingtransfered
    INTERRUPTABLE
    ACTION TRANSFER=Reception
}

Day Menu.Dial By Name.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Dial By Name.1
}

Day Menu.Dial By Name.1
{
    INTERRUPTABLE
    ACTION NODE=Dial By Name
}

Day Menu.StarMenu.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.StarMenu.1
}

Day Menu.StarMenu.1
{
    INTERRUPTABLE
    ACTION NODE=StarMenu
}

Day Menu.Invalid Option Return.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Invalid Option Return.1
    EVENT RESULT.Next=\
}

Day Menu.Invalid Option Return.1
{
    MSG invalidoption
    INTERRUPTABLE
    ACTION NULL=
    RESULT=Next
}

Day Menu.Transfer to Extension.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Transfer to Extension.1
}

Day Menu.Transfer to Extension.1
{
    MSG yourebeingtransfered
    INTERRUPTABLE
    ACTION TRANSFER=$KEY
}

Day Menu.CHANGE ??? TO REFLECT DIAL PLAN.0
{
    INTERRUPTABLE
    ACTION WAIT
}

Day Menu.Conf Bridge.0
{
    INTERRUPTABLE
    ACTION WAIT
    EVENT RESULT.NODE_ENTRY=Day Menu.Conf Bridge.1
}

Day Menu.Conf Bridge.1
{
    INTERRUPTABLE
    ACTION NODE=Conf Bridge
}
...

Thanks.

 

[Westi]

I am not sure about the $ though it can be anything and it might screw you up, take it out for testing and try again if it works then.
You can use the checkmark invalid in the menu and have that point go to the invalid option rather than using the $. That is of course if you run a recent version.

Joe W.

FHandw., ACS (downgraded again)

insanity is just a state of mind

 

[zachlac]

Removing the dollar sign had no effect. I would think that if it was related to the flow of Voicemail Pro, that it would fail for internal calls as well, since they are routed through the system in the same way. I'd think it would be something to do with external settings, possibly line settings or the like, but they all seem to be correct. Any ideas?

 

[CarGoSki]

What does sysmon say about it? aka post sysmon traces. Should be able to see the attempted transfer and destination and disconnect and disconnect cause.

It's people like you who generalize.

 

[zachlac]

I'm running SysMon, and it can trace processes, but it doesn't provide the information you're mentioning (

http://www.sysmon.com).

It gives process creation/termination, but no specific vmpro or IP Office info. Is there a different version of sysmon?

 

[amriddle01]

No, as in C:\Program Files\Avaya\IP Office\Monitor\SysMonitor.exe run that and post traces

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[zachlac]

Ah, ok. When I start this program it sits an "trying to connect" forever, even after I switch the IP address and password. There is nowhere to input the user name. Is there a setting in the IP office configuration which needs to be set?

 

[amriddle01]

It's a different password, the same as you use for upgrading, often still "password" no user name is required

ACS - IP Office Implement

"What the Crocodile Hat....was that?

 

[zachlac]

Ah, finally! Thanks

I've posted a failed call from the outside (

http://www.box.net/shared/b8h9yxp84u

) and a successful call through the system from the inside (

http://www.box.net/shared/5h1eq3fry4

). Names and numbers obscured, obviously. One thing strikes me about the outside call:

20315mS CMLineTx: v=1
            CMFacility
            Line: type=Q931Line 1 
            Call: lid=1 id=1 in=1
            Product Unknown
            IE CMIESupplementaryService (5)
              Network Facility Extension
                sourceEntity: 0
                destinationEntity: 0
              Interpretation APDU
                discardAnyUnrecognisedInvokePdu
              CallTransferActive.Invoke
                invokeId  14624
   20397mS CMLineRx: v=1
            CMReleaseComp
            Line: type=Q931Line 1 
            Call: lid=1 id=1 in=1
            BChan: slot=2 chan=23
            Product Unknown
            Cause=98, Message not compatible with call state, non-existant or not implemented
[\code]

What does this mean?

And thanks for the responses: it's refreshing to get useful help on a forum :)

 

[tlpeter]

Cause=98 means this:

Cause No. 98 - message not compatible with call state or message type non-existent.
This cause indicates that the equipment sending this cause has received a message such that the procedures do not indicate that this is a permissible message to receive while in the call state, or a STATUS message was received indicating an incompatible call state.


ACS IP Office or is it ACSS
ACA - Implement IP Telephony -- ACA - Design IP Telephony
ACA - Voice Services Management
______________
Women and cats can do as they please and men and dogs should relax and get used to the idea!

 

[zachlac]

I"m having trouble understanding what that actually means: are they referring to the message sent to IP Office from the Voicemail Pro system? Are there any other traces I could do to pinpoint the problem more accurately?

 

[CarGoSki]

Groovy. Sounds like you have perhaps a goofy pri protocol issue. Turn on ISDN layer 1,2,3 and post the failed call again. Also can you tell us how your PRI is setup? Do you know how your provider is set and what equipment they are using for your circuit.

For giggles you may want to swap out the transfer action for assisted transfer action

It's people like you who generalize.

 

[zachlac]

The line is set up as follows:
Switch Type: 5ESS (what the provider told me, I'll have to double-check with them)
Line Type: PRI
Clock quality: Network
CRC: enabled
CSU Operation: disabled
Framing: ESF
Zero suppression: B8ZS
Line signalling: CPE

The new fail call is posted here:

http://www.box.net/shared/voa59ur7qv

Could it be a problem with mismatching switch types? I tried setting it to NS1, since I read on another post that someone else did this and it fixed a problem, but nothing changed.

EDIT: Assisted transfer works. Great!!!

Not sure what the problem is/was. I'm trying to set it up so that assisted transfer still gives us the "I'm sorry...<NAME> is not available. After the tone..." instead of just "record message after tone". Minor problem though!

Possibly the assisted transfer fills in an invalid CLI or something like that?