Annotated logs for utterance capturing.

Turn on micro trace VUI : Capture Utterances

Look in diag_CuCsMgr_X.log files.

07/28/2008 16:34:13.975 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMessagesCount.cde!PlayMessagesCount] [Src/CsStateMachine.cpp:139]|

07/28/2008 16:34:16.065 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,VUI,5,Phrase='PlayMessagesCount', Grammar='VuiSubMenuGrammar', Event='SpeechMatch', Meaning='Help', Input='help', Confidence='93', WaveformFile='/var/opt/cisco/connection/log/asr/EIIOFHHFAAAMKENEAAAAAAAA/20080728163413_980683.wav', Session='EIIOFHHFAAAMKENEAAAAAAAA' (Src/CsPhrase.cpp:921)|

This log provides information about a speech event. The Input field is the actual text that the ASR engine matched in the grammar. The Confidence field is a score from 0 to 100 indicating the likelihood of this being the correct result. The WaveformFile field is the path to the utterance wave file. The Session is the MRCP session id. Note that you can retrieve the wave files using RTMT.

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMessagesCount.cde!PlayMessagesCount] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:143]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Event is [Help] [Src/CsStateMachine.cpp:168]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Next state is [NULL] [Src/CsStateMachine.cpp:190]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Exiting state machine. [Src/CsStateMachine.cpp:227]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!RunVuiSubMessagesCount] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:143]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Event is [Help] [Src/CsStateMachine.cpp:168]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] [Src/CsStateMachine.cpp:190]|

07/28/2008 16:34:16.066 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] [Src/CsStateMachine.cpp:139]|

07/28/2008 16:34:19.518 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,VUI,2,DOMDocument::getDocumentElement returned NULL (Src/CsVuiSpeechResult.cpp:74)|

07/28/2008 16:34:19.518 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,VUI,5,Phrase='PlayHelp', Grammar='VuiSubMenuGrammar', Event='SpeechNoMatch', Meaning='', Input='', Confidence='', WaveformFile='/var/opt/cisco/connection/log/asr/EIIOFHHFAAAMKENEAAAAAAAA/20080728163416_069678.wav', Session='EIIOFHHFAAAMKENEAAAAAAAA' (Src/CsPhrase.cpp:921)|

In this case, the user uttered something that the ASR engine couldn’t match. Listen to the captured utterance file to debug the situation. Note that the Event field is set to SpeechNoMatch instead of SpeechMatch.

07/28/2008 16:34:19.519 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:143]|

07/28/2008 16:34:19.519 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Event is [SPEECH_NOMATCH_EVENT] [Src/CsStateMachine.cpp:168]|

07/28/2008 16:34:19.519 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/VuiSubMenu.cde!SorryIMissedThat2] [Src/CsStateMachine.cpp:190]|

07/28/2008 16:34:19.519 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!SorryIMissedThat2] [Src/CsStateMachine.cpp:139]|

07/28/2008 16:34:21.229 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!SorryIMissedThat2] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:143]|

07/28/2008 16:34:21.229 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Event is [NULL] [Src/CsStateMachine.cpp:168]|

07/28/2008 16:34:21.229 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Next state is [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] [Src/CsStateMachine.cpp:190]|

07/28/2008 16:34:21.230 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Calling OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] [Src/CsStateMachine.cpp:139]|

07/28/2008 16:34:23.889 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,VUI,5,Phrase='PlayHelp', Grammar='VuiSubMenuGrammar', Event='SpeechMatch', Meaning='SendRequest', Input='send message', Confidence='96', WaveformFile='/var/opt/cisco/connection/log/asr/EIIOFHHFAAAMKENEAAAAAAAA/20080728163421_233483.wav', Session='EIIOFHHFAAAMKENEAAAAAAAA' (Src/CsPhrase.cpp:921)|

Here is another case of a speech match. Notice that the Input is “send message.” If you listen to the utterance file, it should roughly sound like “send message.”

07/28/2008 16:34:23.889 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : OnEntry for state [/opt/cisco/connection/share/tui/VuiSubMenu.cde!PlayHelp] returned 0x00000000 S_OK [Src/CsStateMachine.cpp:143]|

07/28/2008 16:34:23.889 |2734,PhoneSystem-1-001,9B0F4461536C4D4799F22A4F2956C9B3,CDE,10,CCsStateMachine::Execute : Event is [SendRequest] [Src/CsStateMachine.cpp:168]|

In addition, the Remote Port Status Monitor (rPSM) also contains this information in a more dynamic and readable form.

16:42:58, New Call, CallerId=3000, CalledId=8000, RedirectingId=, Origin=16, Reason=1, CallGuid=9B0F4461536C4D4799F22A4F2956C9B3, CallerName=, LastRedirectingId=, LastRedirectingReason=1024, PortDisplayName=PhoneSystem-1-001

[Origin=Unknown] [Reason=Direct]

16:42:58, Changed the current search by extension search space from <No scope> to 'cuc-install-1 Search Space' ({ddd84682-bb01-4189-9245-18d18bbc4dee})

16:42:58, Changed the current search by name search space from <No scope> to 'cuc-install-1 Search Space' ({ddd84682-bb01-4189-9245-18d18bbc4dee})

16:42:58, AttemptSignIn

16:42:58, State - AttemptSignIn.cde!Dummy

16:42:58, Event is [NULL]

16:42:58, SubSignIn

16:42:58, Subscriber Sign-In

16:42:58, State - SubSignIn.cde!AnswerPhone

16:42:58, Event is [TrueEvent]

16:42:58, State - SubSignIn.cde!AuthenticateUser

16:42:58, -->SubAuthenticate

16:42:58, State - SubAuthenticate.cde!TryCounter

16:42:58, Event is [NULL]

16:42:58, State - SubAuthenticate.cde!GatherID

16:42:58, Event is [FalseEvent]

16:42:58, State - SubAuthenticate.cde!LoadSubscriberMinimalData

16:42:58, Event is [NULL]

16:42:58, State - SubAuthenticate.cde!GatherPIN

16:42:58, -->SubAuthenticatePW

16:42:58, State - SubAuthenticatePW.cde!ValidatePwd

16:42:59, Subscriber sign-in successful. Alias - benshan. Extension - 3000. Caller Id - 3000.

16:42:59, Changed the current search by extension search space from 'cuc-install-1 Search Space' ({ddd84682-bb01-4189-9245-18d18bbc4dee}) to 'all' ({fc96c663-cb05-426a-8437-181afb0b28f8})

16:42:59, Changed the current search by name search space from 'cuc-install-1 Search Space' ({ddd84682-bb01-4189-9245-18d18bbc4dee}) to 'all' ({fc96c663-cb05-426a-8437-181afb0b28f8})

16:42:59, Event is [TrueEvent]

16:42:59, State - SubAuthenticatePW.cde!ReturnAuthenticated

16:42:59, Event is [Authenticated]

16:43:00, <--SubAuthenticatePW

16:43:00, Event is [Authenticated]

16:43:00, State - SubAuthenticate.cde!ReturnAuthenticated

16:43:00, Event is [Authenticated]

16:43:00, <--SubAuthenticate

16:43:00, Event is [Authenticated]

16:43:00, State - SubSignIn.cde!RunSignInUtil

16:43:00, -->SubSignInUtil

16:43:00, State - SubSignInUtil.cde!CheckAccountLocked

16:43:00, Event is [FalseEvent]

16:43:00, State - SubSignInUtil.cde!CheckExpiredAndNew

16:43:00, Event is [NULL]

16:43:00, State - SubSignInUtil.cde!CheckForExpirationWarning

16:43:00, Event is [NULL]

16:43:00, State - SubSignInUtil.cde!CheckForAdminConversation

16:43:00, Event is [FalseEvent]

16:43:00, State - SubSignInUtil.cde!CheckAlternateGreeting

16:43:00, Event is [FalseEvent]

16:43:00, State - SubSignInUtil.cde!CheckForLeaveMsg

16:43:00, Event is [FalseEvent]

16:43:00, <--SubSignInUtil

16:43:00, Event is [FalseEvent]

16:43:00, State - SubSignIn.cde!RunSignInUtil_default

16:43:00, Event is [NULL]

16:43:00, State - SubSignIn.cde!RunNextConv

16:43:00, -->VuiStart

16:43:00, Ben Shanfelder VUI Login (Mailbox benshan)

16:43:00, State - VuiStart.cde!GetVuiSession

16:43:00, Event is [NULL]

16:43:00, State - VuiStart.cde!Start

16:43:00, Event is [NULL]

16:43:00, State - VuiStart.cde!RunVuiSubMenu

16:43:00, -->VuiSubMenu

16:43:00, State - VuiSubMenu.cde!Start

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMenu.cde!ResumeMessage

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMenu.cde!CheckBypassAlertsAndNotifications

16:43:00, Event is [AlertsAndNotifications]

16:43:00, State - VuiSubMenu.cde!GetMailboxStatusBeforeMenu

16:43:00, Event is [YesEvent]

16:43:00, State - VuiSubMenu.cde!CheckQuotaBeforeMenu

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMenu.cde!CheckAlternateGreetingWarning

16:43:00, Event is [FalseEvent]

16:43:00, State - VuiSubMenu.cde!RunVuiSubMessagesCount

16:43:00, -->VuiSubMessagesCount

16:43:00, State - VuiSubMessagesCount.cde!Start

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMessagesCount.cde!CheckForBroadcastMessage

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMessagesCount.cde!CheckIfMessagesAvailable

16:43:00, Event is [NULL]

16:43:00, State - VuiSubMessagesCount.cde!PlayMessagesCount

16:43:02, Speech: Input='help', Confidence='93', Meaning='Help'

16:43:02, Event is [Help]

16:43:02, <--VuiSubMessagesCount

16:43:02, Event is [Help]

16:43:02, State - VuiSubMenu.cde!PlayHelp

16:43:05, Speech: No-match

16:43:05, Event is [SPEECH_NOMATCH_EVENT]

16:43:05, State - VuiSubMenu.cde!SorryIMissedThat2

16:43:07, Event is [NULL]

16:43:07, State - VuiSubMenu.cde!PlayHelp

16:43:09, Speech: Input='send message', Confidence='96', Meaning='SendRequest'

16:43:10, Event is [SendRequest]

16:43:10, State - VuiSubMenu.cde!HandleSendRequest

16:43:10, Event is [YesEvent]

16:43:10, State - VuiSubMenu.cde!RunVuiSubSend

16:43:10, -->VuiSubSend

16:43:10, State - VuiSubSend.cde!Start

16:43:10, Event is [NULL]

16:43:10, State - VuiSubSend.cde!InitializeRecordStream

16:43:10, Event is [NULL]

16:43:10, State - VuiSubSend.cde!SendConfirmation

16:43:11, Event is [HangupEvent]

16:43:11, <--VuiSubSend

16:43:11, Event is [HangupEvent]

16:43:11, <--VuiSubMenu

16:43:11, Event is [HangupEvent]

16:43:11, <--VuiStart

16:43:11, Event is [HangupEvent]

16:43:12, Idle

When we get a no-match back from the ASR engine, we don’t have any information about what the user may have said. The call logs contain more information. You will need root access to get them. They are under /var/opt/cisco/connection/log/callLogs. Browse to the folder with the correct date. The relevant file will have the same MRCP session id as above. Open the log and search for “lowconf”. In the case above, we see:

TIME=20080728163419514|CHAN=EIIOFHHFAAAMKENEAAAAAAAA|EVNT=SWIrcnd|RSTT=lowconf|RENR=prun|ENDR=itimeout|NBST=8|RSLT={cisco:{MEANING:Cancel}}|RAWT=cancel|SPOK=cancel|GRMR=GURI0|KEYS=<cisco.MEANING conf="11">Cancel</cisco.MEANING><SWI_confidence conf="0">0</SWI_confidence>|CONF=11|RAWS=-730.098572|RSLT={cisco:{MEANING:VuiIncreaseSpeed}}|RAWT=faster|SPOK=faster|GRMR=GURI0|KEYS=<cisco.MEANING conf="11">VuiIncreaseSpeed</cisco.MEANING><SWI_confidence conf="0">0</SWI_confidence>|CONF=11|RAWS=-732.435974|SPMS=en.us_SecondPass4|MDVR=1809628356|NADP=0|CADP=0|LADP=N/A|MPNM=en-us/models4|DPNM=NA|MACC=NULL|MEDIA=audio/basic;rate:8000|EOSS=1000|DURS=1010|EOSD=1500|BORT=57|EOST=1180|EORT=1798|EOFT=1327|CPRT=1118|CPAR=0.292,0.168,-0.562,0.461,0.177,0.039,0.058,1.000,1.000,0.154,-1.291|LA=idle|OFFS=0.000000|SCAL=1.000000|SRCH=SB:0.0,WB:-78.0,PLB:-75.0,SPO:56.0,MA:6000|RSWT=2:1.0000,3:1.0000|RCPU=180|UCPU=9150|SCPU=2830

From this example, the ASR engine thought the best match was “cancel.” The confidence score is 11 out of 1000. This log information can be very useful when dealing with a foreign accent not being recognized by the ASR engine. In those cases, the above log will show that the engine recognized what’s in the actual captured wave utterance, but the confidence score was too low.

Note that the ASR engine call logs are always turned on.