AAEP/Nuance: MRCPv2 stability issue between AAEP 7.0.1 and Nuance Recognizer 9

Doc ID    SOLN275017
Version:    1.0
Status:    Published
Published date:    12 Sep 2015
Author:   
Sandeep ParvathReddy
 

Details

================
Products Involved
================
AAEP 7.0.1
1 X EPM
1 X MPP
10 ASR/TTS/Telephony SIP
3 Nuance ASR lic,
2 TTS Loquendo with 2 lic each
Nuance Recognizer 9 on Windows Server 2008 R2 Standard
MRCPv2 protocol being used.

Nuance Recognizer 9.0.19 with Nuance Speech Server 5.1.8.
========================
Nortel CS1000 SIP GW release_7.0 version_ssLinux-7.65.16
AVAYA-SM-6.3.13.0.631304

Problem Clarification

After migration from AAEP 6 SP2 to AAEP 7.0.1

After migrating Avaya Aura Experience Portal 6 to 7 the following alarm shows frequesntly:
PMRCP00008 - The connection to the server [WXXXASR01] has failed! Server:WXXXASR01 File:asr/MrcpASRServer.cpp Line:FileName=asr/MrcpASRServer.cpp LineNumber=51

Also the ASR connection was being dropped causing the call to end abruptly.

Customer was using es-es language.

Logs snippet belongs to a unique call, which loses ASR resource several seconds after it starts. Before losing the ASR resource, ASR has successfully recognized a 8 digits input, and a 4 digits input.

SessMgr logs: 
@2015-08-06 10:52:27,176||FINER|SessMgr|25562||Prompt play is finised with recognition active, starting no input timer [5000]..., bargein = 1|ltbampp01####
@2015-08-06 10:52:27,176||FINER|SessMgr|25562||Prompt play was not completed and bargein = 1.|ltbampp01####
@2015-08-06 10:52:27,176||FINER|SessMgr|25562||Sending VXML message to session 1, Message type = VXML_PROMPT_PLAY_COMPLETE, VXI = VXMLMGR|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Entering Dialog.cpp:6580:PromptClearQueue|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:6580:PromptClearQueue|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Entering Dialog.cpp:4911:ASRRecognitionResult|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Entering Dialog.cpp:3810:ASR_Stopped|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||ASR_Stopped: Stopped ASR|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:3810:ASR_Stopped|ltbampp01####
@2015-08-06 10:52:27,177||FINE|SessMgr|25562||Processing RecResult: [ASRError] : [], utterance URL [], bargein = 1|ltbampp01####
@2015-08-06 10:52:27,177||FINER|SessMgr|25562||Sending VXML message to session 1, Message type = VXML_REC_ERROR, VXI = VXMLMGR|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Entering Dialog.cpp:7277:ReportAppError|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Entering Session.cpp:4095:ReportAppError|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Leaving Session.cpp:4095:ReportAppError|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:7277:ReportAppError|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|SessMgr|25562||CDialog::ASRRecognitionResult: Fatal ASR Error has occured...|ltbampp01####
@2015-08-06 10:52:27,177||FINE|SessMgr|25562||CDialog::ASRRecognitionResult: Releasing ASR Port -146746216, due to fatal error (ASR OnError)|ltbampp01####
@2015-08-06 10:52:27,177||FINER|SessMgr|25562||CASRPortCtrl::Disconnect, disconnecting Endpoints 4 -> 1, Use Count = 1|ltbampp01####
@2015-08-06 10:52:27,237||FINE|MRCP|2847|FileName=asr/MrcpASRPort.cpp,LineNumber=442|ProcStopSession Port:4 State:IDLE MRCPSess: VPSess: Server:WXXXASR01.gneis.gs/media/speechrecognizer File:asr/MrcpASRPort.cpp Line:442|ltbampp01####
@2015-08-06 10:52:27,237||FINE|MRCP|2847|FileName=asr/MrcpASRPort.cpp,LineNumber=445|MRCPv2 Port:4 State:IDLE MRCPSess: VPSess: Server:WXXXASR01.gneis.gs/media/speechrecognizer File:asr/MrcpASRPort.cpp Line:445|ltbampp01####
@2015-08-06 10:52:27,237||FINE|MRCP|2847|FileName=asr/MrcpASRPort.cpp,LineNumber=1782|UNKNOWN:RESULT_OK: Port:4 State:IDLE MRCPSess: VPSess: Server:WXXXASR01.gneis.gs/media/speechrecognizer File:asr/MrcpASRPort.cpp Line:1782|ltbampp01####
@2015-08-06 10:52:27,237|PMRCP00005|WARN|MRCP|2847|FileName=asr/MrcpASRPort.cpp,LineNumber=1967|No event reporter callback is registered for ASR. Port:4 State:IDLE MRCPSess: VPSess: Server:WXXXASR01.gneis.gs/media/speechrecognizer File:asr/MrcpASRPort.cpp Line:1967|ltbampp01####
@2015-08-06 10:52:27,237||FINE|MRCP|2847|FileName=asr/MrcpASRPort.cpp,LineNumber=1968|No event reporter assigned Port:4 State:IDLE MRCPSess: VPSess: Server:WXXXASR01.gneis.gs/media/speechrecognizer File:asr/MrcpASRPort.cpp Line:1968|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:4911:ASRRecognitionResult|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:6668:SendPlayComplete|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:6748:ProcessPromptNodeComplete|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:6748:ProcessPromptNodeComplete|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:2619:ProcessPlayDone|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:8098:ProcessEndPointMsg|ltbampp01####
@2015-08-06 10:52:27,239||FINEST|SessMgr|25562||******** Leaving Dialog.cpp:8330:ProcessMsg|ltbampp01####
 
 MediaMgr logs: 
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Entering EndPointMgr.cpp:1413:OnMediaStopped|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||OnMediaStopped - RTPStats for EndPoint 4, [10.111.19.11:7892, 20, 0, 0, 1943, 0, 0, 0, 8, 0, ]|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Entering EndPointMgr.cpp:2072:SendEndPointMessage|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Entering EndPointMgr.cpp:279:SendEndPointMessage|ltbampp01####
@2015-08-06 10:52:27,176||FINER|MediaMgr|2817||CEndPointChannel::SendEndPointMessage: Sending EndPoint message on Channel SessionManager - 3 to EndPoint 4, Message type(25) = MediaStopped|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||SendEndPointMessage - Message Content: type: MediaStopped
endpointID: 4
RTPStats.remoteRtpAddress: 10.1X1.X9.XX1
RTPStats.remoteRtpPort: 7892
RTPStats.localRtpAddress: 10.1X1.X9.XX0
RTPStats.localRtpPort: 23002
RTPStats.codec: 1
RTPStats.packetSize: 20
RTPStats.packetsSent: 1943
RTPStats.packetsLost: 8
RTPStats.jitter: 0
RTPStats.packetsReceived: 0
RTPStats.packetsReportedLost: 0
RTPStats.reportedJitter: 0
RTPStats.roundTripTime: 0
RTPStats.mediaEncryptionActive: 0
RTPStats.mediaEncryptionType:
RTPStats.securePktCount: 0
RTPStats.duplicatePktCount: 0
RTPStats.wrapPktCount: 0
RTPStats.authFailPktCount: 0
, size 132|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Leaving EndPointMgr.cpp:279:SendEndPointMessage|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Leaving EndPointMgr.cpp:2072:SendEndPointMessage|ltbampp01####
@2015-08-06 10:52:27,176||FINEST|MediaMgr|2817||******** Leaving EndPointMgr.cpp:1413:OnMediaStopped|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:35:ProcessMediaMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:359:ProcessMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINER|MediaMgr|2743||SessionManager Process MSG : 4 : 39|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||ProcessMessage - Message Content: type: MediaStop
endpointID: 4
reason: 0
|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:2272:StopMedia|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||Media: Stopping Media on endpoint 4|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Leaving EndPointMgr.cpp:2272:StopMedia|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Leaving EndPointMgr.cpp:359:ProcessMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|MediaMgr|2743||******** Leaving EndPointMgr.cpp:35:ProcessMediaMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINER|Tele|2743|FileName=VPMediaManager.cpp,LineNumber=1137|VPMediaManager::MediaStop: Endpoint=4 Reason=0|ltbampp01####
@2015-08-06 10:52:27,177||FINER|Tele|2818|FileName=MediaManager.cpp,LineNumber=439|[0xeacdd008]MediaManager::ProcessStopMedia: EndpointID=4 Reason=0|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|Tele|2818|FileName=media/ChannelEndpoint.cpp,LineNumber=522|ChannelEndpoint::StopMedia: EndpointID=4 Reason=CHANNEL_COMPLETE|ltbampp01####
@2015-08-06 10:52:27,227||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:35:ProcessMediaMessage|ltbampp01####
@2015-08-06 10:52:27,227||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:359:ProcessMessage|ltbampp01####
@2015-08-06 10:52:27,227||FINER|MediaMgr|2743||SessionManager Process MSG : 4 : 39|ltbampp01####
@2015-08-06 10:52:27,227||FINEST|MediaMgr|2743||ProcessMessage - Message Content: type: UnjoinEndPoints
endpointID: 4
endpointID2: 1
|ltbampp01####
@2015-08-06 10:52:27,227||FINEST|MediaMgr|2743||******** Entering EndPointMgr.cpp:2224:UnjoinEndpoints|ltbampp01####
@2015-08-06 10:52:27,227||FINEST|MediaMgr|2743||Media: Unjoining endpoints 4 -> 1|ltbampp01####
@2015-08-06 10:52:27,227||FINER|Tele|2743|FileName=VPMediaManager.cpp,LineNumber=1602|VPMediaManager::UnjoinEndpoints: EndpoinID1=4 EndpointID2=1|ltbampp01####
@2015-08-06 10:52:27,227||FINER|Tele|2818|FileName=MediaManager.cpp,LineNumber=377|[0xeacdd008]MediaManager::ProcessUnjoinEndpoints: EndpointID1=4 EndpointID2=1|ltbampp01####
  
VB logs: 
@2015-08-06 10:52:27,177||FINE|VB|25566|Session=ltbampp01-2015218085142-1|received a VXML_REC_ERROR|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|VB|25566|Session=ltbampp01-2015218085142-1|******** Entering Utility.cpp:489:LogIPCMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|VB|25565|Session=ltbampp01-2015218085142-1|******** Leaving vpchannel.cpp:6540:QueueMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|VB|25565|Session=ltbampp01-2015218085142-1|successfully added msg to channel queue|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|VB|25565|Session=ltbampp01-2015218085142-1|******** Leaving Dialog.cpp:349:ProcessInboundMessage|ltbampp01####
@2015-08-06 10:52:27,177||FINEST|VB|25566|Session=ltbampp01-2015218085142-1|VXML_REC_ERROR
{
                dialogHandle: 1
                code: NO_ASR_RESOURCE
                description: "ASR Error"
                haveUtterance: 0
                utteranceDuration: 0
                utterancePath: ""
 
   
SessionManger component global log:
@2015-07-16 22:38:51,146||FINE|Tele|20430|FileName=sip/SIPUAManager.cpp,LineNumber=1475|SIPUAManager::TrunkOutOfService: TrunkId=5 Reason=Unable To Connect to proxy|ltbampp01####
@2015-08-05 10:25:12,434||FINE|Tele|25719|FileName=sip/SIPUAManager.cpp,LineNumber=1475|SIPUAManager::TrunkOutOfService: TrunkId=5 Reason=Unable To Connect to Proxy|ltbampp01####
@2015-08-06 10:52:27,175||FINE|Tele|2783|FileName=sip/SIPUAManager.cpp,LineNumber=1475|SIPUAManager::TrunkOutOfService: TrunkId=5 Reason=Unable To Connect to Proxy|ltbampp01####
 
 
@2015-07-16 22:32:34,312||FINE|Tele|20430|FileName=sip/SIPUAManager.cpp,LineNumber=1177|SIPUAManager::OnSIPConnectionError: Failure on socket 90:456 to 10.1X1.1X9.1XX:5060|ltbampp01####
@2015-08-05 10:25:12,434||FINE|Tele|25719|FileName=sip/SIPUAManager.cpp,LineNumber=1177|SIPUAManager::OnSIPConnectionError: Failure on socket 84:2 to 10.1X1.1X9.1XX:5060|ltbampp01####
@2015-08-06 10:52:37,296||FINE|Tele|2783|FileName=sip/SIPUAManager.cpp,LineNumber=1177|SIPUAManager::OnSIPConnectionError: Failure on socket 82:14120 to 10.1X1.1X9.1XX:5060|ltbampp01####

 

Cause

This only happens when there is a voice installed which is not in langtable.txt.
That means the problem only exist when there is no language information available for the OPTION request.

This does not happen often because most installations does have more than on language installed. And only es-es is not by default defined in langtable.txt.

Solution

After changing the langtable.txt with correct entries of the language being used the issue was resolved.

This issue has been fixed in NSS6.2.7. It is not a Recognizer issue.

This only happens when there is a voice installed which is not in langtable.txt. on the Nuance side
That means the problem only exist when there is no language information available for the OPTION request.

This does not happen often because most installations does have more than one language installed. And only es-es is not by default defined in langtable.txt.

PSN has been released on the Avaya support portal...  http://downloads.avaya.com/css/P8/documents/101014981

 


Avaya -- Proprietary. Use pursuant to the terms of your signed agreement or Avaya policy