Some calls skipping autoattendant, transferred to HG instead

[sceaton]

Hello,

IPO500V1, v5.0(24) with VM PRO. PRI service.

Calls to main number are configured to transfer to VM Autoattendant named "incoming". Ocasionally, some calls will route directly to a hunt group, bypassing the autoattendant altogether.

I have a HG named "incoming" to route calls in the event the VMPRO server is unavailable, but that directs calls to HG 300, these random calls are being directed to HG 303.

I can't figure out why they're ending up there. The caller says they don't hear any prompts, just ringing (directly to the HG 303).

Here's a monitor trace of a sample call (phone number redacted):

4065222676mS VMAIL: SESS 641f: CMD=1 Mailbox=incoming Access=4 !Internal!=N Calling_party_number=9xxxxxx4363  targeted_party_number= Called_party_number= Display=9xxxxxx4363>incoming
4065222677mS VMAIL: SESS 641f: CMD=9 Mailbox=incoming Access=4 !Internal!=N Calling_party_number=9xxxxxx4363  targeted_party_number= Called_party_number= Display=9xxxxxx4363>incoming
4065222677mS ISDNL1Tx: v=1 peb=1
            0000 02 01 01 3a                                     ...:
4065222739mS RES: Tue 5/2/2013 10:16:11 FreeMem=69259092(1) CMMsg=11 (12) Buff=200 948 999 7362 3 Links=21778
4065222739mS RES2: IP 500 5.0(24) Tasks=33 RTEngine=0 CMRTEngine=0 Timer=63 Poll=0 Ready=2 CMReady=0 CMQueue=0 VPNNQueue=0 Monitor=1
4065223096mS ISDNL1Rx: v=1 peb=1
            0000 02 01 3a 1e 08 02 03 35 62 1c 1c 9f 8b 01 00 a1 ..:....5b.......
            0010 16 02 01 01 02 01 00 80 0e 53 50 45 4e 43 45 52 .........SPENCER
            0020 20 45 41 52 4c 20 26                             EARL &
4065223097mS ISDNL2Rx: v=1 peb=1
            0000 02 01 3a 1e 08 02 03 35 62 1c 1c 9f 8b 01 00 a1 ..:....5b.......
            0010 16 02 01 01 02 01 00 80 0e 53 50 45 4e 43 45 52 .........SPENCER
            0020 20 45 41 52 4c 20 26                             EARL &
4065223097mS ISDNL3Rx: v=1 peb=1
            ISDN Layer3 Pcol=08(Q931) Reflen=2 ref=0335(Remote)
            Message Type = Facility
                InformationElement = FAC
             0000 1c 1c 9f 8b 01 00 a1 16 02 01 01 02 01 00 80 0e ................
             0010 53 50 45 4e 43 45 52 20 45 41 52 4c 20 26       SPENCER EARL &
4065223097mS ISDNL2Tx: v=1 peb=1
            0000 02 01 01 3c                                     ...<
4065223098mS ISDNL1Tx: v=1 peb=1
            0000 02 01 01 3c                                     ...<
4065223098mS CMLineRx: v=1
            CMFacility
            Line: type=Q931Line 1 Call: lid=1 id=2 in=1
            IE CMIESupplementaryService (3)
              Interpretation APDU
                rejectAnyUnrecognisedInvokePdu
              CallingName.Invoke.CodePageISO8859-1
                invokeId  1
                  user 'SPENCER EARL &' presentation Allowed
4065223099mS CMExtnTx: v=RAS, p1=0
            CMFacility
            Line: type=RAS 1 Call: lid=0 id=1013 in=0
            Called[] Type=Default (100) Reason=CMDRdirect  Calling[9xxxxxx4363] Type=Unknown Plan=ISDN Pres=Allowed (0) 
            BChan: slot=21 chan=43
            IE CMIESupplementaryService (3)
              Interpretation APDU
                rejectAnyUnrecognisedInvokePdu
              CallingName.Invoke.CodePageISO8859-1
                invokeId  1
                  user 'SPENCER EARL &' presentation Allowed
            IE CMIERespondingPartyNumber (230)(P:0 S:1 T:0 N:1 R:4) number=9xxxxxx4363
            IE CMIEDeviceDetail (231) LOCALE=enu HW=8 VER=5 class=CMDeviceISDNTrunk type=2 number=1 channel=13 rx_gain=32 tx_gain=32 ep_callid=2 ipaddr=172.18.12.5 apps=0
            IE CMIECallingPartyName (110)(Type=CMNameDefault) name=SPENCER EARL &
            IE CMIERespondingPartyName (228)(Type=CMNameDefault) name=SPENCER EARL &
4065226521mS CMExtnRx: v=RAS, p1=0
            CMFacility
            Line: type=NoLine 0 Call: lid=0 id=-1 in=0
            Called[CLAIM] Type=ACD (103) Reason=CMDRdirect  
4065226528mS VMAIL: VMMESSAGE Transfer request [303]
4065226528mS CMExtnRx: v=RAS, p1=0
            CMTransfer
            Line: type=NoLine 0 Call: lid=0 id=-1 in=0
            Called[303] Type=Default (100) Reason=CMDRdirect  SndComp 
4065226529mS CMCallEvt:    0.201383.0 35592 RAS.0: Transfer CMCauseTransfer
4065226529mS CDR: Initialising communications [IP Address = 0.0.0.0, port 1150 [TCP]]
4065226529mS PRN: CDR - ResetQueueSize=500
4065226530mS PRN: CDR - TCPSend maxqueuesize=500 operational=0
4065226530mS ERR: CDRServer discarding - framecount=500
4065226530mS CD: CALL: 1.2.1 BState=Connected Cut=3 Music=0.0 Aend="Line 1" (1.14) Bend="incoming(incoming)" [VoiceMail] (21.43) CalledNum=incoming () CallingNum=9xxxxxx4363 (SPENCER EARL &) Internal=0 Time=3896 AState=Connected
4065226531mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: ADD TARGET (N): number=303 type=100 depth=1 nobar=1 setorig=1 ses=0
4065226531mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: HG(Wellness Group,303,172.18.12.5) Requires Routing To Master(1). IsLocalExecutive(1)
4065226531mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: HG call targeting occuring here
4065226531mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: PrimeForHGTarget: Wellness Group setorig=1 recall=0 resetExtnVars 1
4065226531mS CMCallEvt:    Priority hike: call 35592 priority 1->5
4065226532mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: AddHGTarget Wellness Group (depth=2) allowq=1 type=CMNTypeDefault 
4065226532mS CMCallEvt:    0.201384.0 -1 BaseEP: NEW CMEndpoint f525f1b8 TOTAL NOW=9 CALL_LIST=4
4065226532mS CMTARGET:     1.2.1 35592 Q931 Trunk:1 CHAN=13: PrepareTransferTargets Found 1 target

I've looked through the incoming call routes and Fallback settings and VM call flows but can't figure out how they're getting directly to HG 303.

Any ideas?

Thanks!

 

[CarGoSki]

Perhaps you should run dbgview and examine those traces since: 4065226528mS VMAIL: VMMESSAGE Transfer request [303]

 

[hairlessupportmonkey]

Is your switch called "Wellness Group" and you have a group called "Wellness Group" too?

ACSS - SME
General Geek

 

[sceaton]

I didnt know about dbgview ... I'll see what that turns up.

And no, the switch is called something different. Wellness Group is the name of the group where random calls are ending up without first hearing the menu.

 

[sceaton]

Well, dbgview claims it heard a "4" which is the option to connect to the Wellness Group HG.

05/02 10:16:16.133 vmprov5s (1b,5) 6a0, 808: IClient:tmfDetect 0D2500E8 '4 (52)' at 720, length 240 - session:0000641f

I've asked for another call example from the user and I'll see if there's a pattern. I also asked them to find out if the caller happend to dial a "4".

"Stupid computers. They do exactly what you tell them to!

 

[tlpeter]

Or do you have that group as fallback in the incoming callroute?
Perhaps all the VM ports where all in use?


BAZINGA!

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

 

[sceaton]

So, more call examples (apparently this is a frequent occurrance today) and each of them show DtmfDetect of a "4". The callers said they start to hear the autoattendant greeting and then they're immediately sent to the Wellness Group, but they did NOT actually press "4".

I already checked the incoming call route fallback, it directs to a different group.

What would cause VMPro to erroneously "hear" a digit? Does it get DTMF passed through out-of-band from the PRI signalling channel via IPO, or does the IPO "play" that tone to the VMPro server?

How do I further troubleshoot this? The wellness group is annoyed with calls that are not for them. You could say they're becoming unwell.

 

[sceaton]

05/02 10:55:41.883 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Executing node day.Day menu.Body.0
05/02 10:55:41.883 vmprov5s (23,5)  6a0, 808:   Succeeded in loading sound bite d:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\day.WAV [uLaw]
05/02 10:55:41.883 vmprov5s (06,5)  6a0, 808:   VMClient::RxOpen - Created dialog 04A62100
05/02 10:55:41.883 vmprov5s (09,4)  6a0, 808:   Session: 00006464 -  - Internal: !Internal!=N
05/02 10:55:41.883 vmprov5s (0a,5)  6a0,16e0: OSThreadFunc entered[VMClient, 04C41020]
05/02 10:55:41.883 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Configuring for reliable disconnect, IDLE time is 300.000s
05/02 10:55:41.883 vmprov5s (06,5)  6a0, 808:   VMClient::RxActive 04C41008 (session=00006464)
05/02 10:55:41.883 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Receive ACTIVE  for session 00006464, call-id 35683
05/02 10:55:45.711 vmprov5s (1b,5)  6a0, 808:   IClient::DtmfDetect 04C410A8 '4 (52)' at 800, length 240 - session:00006464
05/02 10:55:45.711 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Executing request to run node day.Wellness Group.0
05/02 10:55:45.711 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Executing node day.Wellness Group.0
05/02 10:55:45.711 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Executing request to run node day.Wellness Group.1
05/02 10:55:45.711 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - Executing node day.Wellness Group.1
05/02 10:55:45.711 vmprov5s (09,4)  6a0, 808:   Session: 00006464 - SetTransfer=303

05/02 12:35:32.320 vmprov5s (23,5)  6a0, 808:   Succeeded in loading sound bite d:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\day.WAV [uLaw]
05/02 12:35:32.320 vmprov5s (06,5)  6a0, 808:   VMClient::RxOpen - Created dialog 04A5FFC8
05/02 12:35:32.320 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 -  - Internal: !Internal!=N
05/02 12:35:32.320 vmprov5s (0a,5)  6a0, ffc: OSThreadFunc entered[VMClient, 04D01020]
05/02 12:35:32.320 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Configuring for reliable disconnect, IDLE time is 300.000s
05/02 12:35:32.320 vmprov5s (06,5)  6a0, 808:   VMClient::RxActive 04D01008 (session=000064c3)
05/02 12:35:32.320 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Receive ACTIVE  for session 000064c3, call-id 35847
05/02 12:35:36.148 vmprov5s (1b,5)  6a0, 808:   IClient::DtmfDetect 04D010A8 '4 (52)' at 800, length 240 - session:000064c3
05/02 12:35:36.148 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Executing request to run node day.Wellness Group.0
05/02 12:35:36.148 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Executing node day.Wellness Group.0
05/02 12:35:36.148 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Executing request to run node day.Wellness Group.1
05/02 12:35:36.148 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - Executing node day.Wellness Group.1
05/02 12:35:36.148 vmprov5s (09,4)  6a0, 808:   Session: 000064c3 - SetTransfer=303

 

[tlpeter]

Try to record the greeting again but with a different voice.


BAZINGA!

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

 

[sceaton]

Seriously?

 

[CarGoSki]

tlpeter has the correct resolution.
If you were to examine the wav file d:\Program Files\Avaya\IP Office\Voicemail Pro\VM\Wavs\day.WAV with a spectrum analyzer app you would find that dtmf 4 appears in the recorded voice.

In both of your cases:
10:55:45.711 - 10:55:41.883 = 3.172seconds
12:35:36.148 - 12:35:32.320 = 3.172seconds

I would likely find dtmf 4 - 3.172 seconds into day.wav
Use goldwav app to record dtmf 4 then compare the signal to what you see 3.172 seconds into day.wav.
You will likely find a close enough match.

Some people whistle when they talk.

 

[amriddle01]

Some people whistle when they talk.

Indeed, you don't have Charles Kellogg working for you do you?


Avaya Implementation Qualified Professional Specialist Technical Engineer (AIQPSTE)

 

[sceaton]

Ha, well >I'M< the one that recorded them! Now I'm all self conscious that digits are falling out of my mouth when I talk! :-/

 

[CarGoSki]

Use Auto-tune. That would be fun.