001 no-match returned for long utterances. How to change this timeout???

597 views

Skip to first unread message

Robby D

unread,

Sep 18, 2013, 11:06:50 AM9/18/13

to uni...@googlegroups.com

Hi guys,

uni-ast-package-1.1.0, on Ubuntu 12.04.3 x64. I have an app that dials into an IVR interface at regular intervalks and performs speech recognition against the IVR prompts (to ensure that the IVR is still working properly). I'm having an issue with dealing with prompts that are over 20 seconds of speaking before user input is possible (at which point the ASR would register the silence and process the utterance). At that 20 second point (22 seconds in the logs below, although the prompt is 20 seconds in length as gathered on the Nuance Server), it appears that the ASR backend (Nuance Speech Server 5.1 w/ Recognizer v9, using MRCP v2) will return a "001 no-match". It's exactly when the prompt gets to be 20 seconds (or right around 160KB) in length, every time.

I've checked all through the UNIMRCP config files, NSS config file, etc to find this limit and increase it, but for the life of me can't find it:
* In res-speech-unimrcp.conf, modified Recognition-Timeout for mrcpv2 to be 60000
* On the nuance server, changed the max mrcpv2 SIP session length to be 60000 at least, along with a number of other limits
* Tried maxspeechtimeout property in my grammar file I am using
* etc, etc

See logs below, and I can provide any config file contents, etc necessary, just let me know. Thanks!!!

-Robby

----------------------------------------------
Relevant part of the Nuance log below for an example run (I see the inet. Timeouts in this file are 20000...but I can't find how to change them, and if they are relevant):
TIME=20130917215737747|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIfrmt|ENCD=UTF-8|UCPU=0|SCPU=0
TIME=20130917215737747|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIclst|VALU=Session 01e33540-9a87-1231-50ad-005056a870bb started|SRC=SWIrec|UCPU=0|SCPU=0
TIME=20130917215737747|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIliss|SRC=SWIrec|LUSED=1|LMAX=80|OMAX=-1|LFEAT=osr_swirec,osr_rec_u,dtmf|UCPU=0|SCPU=0
TIME=20130917215737747|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=OSCL|OSCC=01e33540-9a87-1231-50ad-005056a870bb|UCPU=0|SCPU=0
TIME=20130917215737747|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIepss|LUSED=1|LMAX=80|OMAX=-1|LFEAT=osr_swiep,ssm_u|UCPU=609|SCPU=0
TIME=20130917215737857|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIgrld|API=SWIrecGrammarLoad|TYPE=string/2.0|PROPS=inet.maxage=31536000;inet.timeoutDownload=20000;inet.timeoutIO=20000;inet.timeoutOpen=20000;inet.urlBase=|FETCHES=0|MEMHITS=0|MEMMISS=2|DISKHITS=0|DISKMISS=1|LDCPU=16|LDTIME=16|GCCPU=0|GCTIME=0|IFCPU=0|IFTIME=0|IFBYTES=0|COMPILES=1|RC=0|UCPU=16|SCPU=0
TIME=20130917215737872|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIgrld|API=SWIrecGrammarActivate|TYPE=string/2.0|WGHT=1|PROPS=inet.maxage=31536000;inet.timeoutDownload=20000;inet.timeoutIO=20000;inet.timeoutOpen=20000;inet.urlBase=|FETCHES=0|MEMHITS=1|MEMMISS=0|DISKHITS=0|DISKMISS=0|LDCPU=0|LDTIME=0|GCCPU=0|GCTIME=0|IFCPU=0|IFTIME=0|IFBYTES=0|COMPILES=0|RC=0|UCPU=16|SCPU=0
TIME=20130917215737872|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIrcst|APNM=MyApp|ACST=1|GURI0=STRING_GRAMMAR|GRNM=STRING_GRAMMAR|LANG=en-us|GRMT=application/srgs+xml|WGHT=1|LIPD=|LNPR=|LPST=none|OSRVER=9.0.18.2011072911|UCPU=0|SCPU=0
TIME=20130917215737872|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIepst|VERSION=9.0.18.2011072911|UCPU=625|SCPU=0
TIME=20130917215759341|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=NUANwvfm|PLAYABLE=NUAN-57-37-speech01site12-01e33540-9a87-1231-50ad-005056a870bb-utt01-PLAYABLE.wav|UCPU=0|SCPU=0
TIME=20130917215759341|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIrcnd|RSTT=lowconf|RENR=prun|ENDR=itimeout|NBST=1|RSLT={SWI_literal:If you are calling about a power outage}|RAWT=If you are calling about a power outage|SPOK=If you are calling about a power outage|GRMR=GURI0|KEYS=<SWI_confidence conf="0">0</SWI_confidence>|CONF=77|RAWS=-16252.436523|WVNM=NUAN-57-37-speech01site12-01e33540-9a87-1231-50ad-005056a870bb-utt01-PLAYABLE.wav|MDVR=2039375232|NADP=0|CADP=0|LADP=N/A|MPNM=en-us/models|DPNM=NA|MACC=NULL|MEDIA=audio/basic;rate:8000|EOSS=20360|DURS=20360|EOSD=20900|BORT=109|EOST=20672|EORT=20703|EOFT=20672|CPRT=571|CPAR=1.000,1.000,1.070,0.449,3.000,0.000,0.014,0.000,0.000,3.000,-0.331|LA=idle|OFFS=0.000000|SCAL=1.000000|SRCH=SB:-75.0,WB:-78.0,PLB:-75.0,SPO:70.0,MA:6000|RSWT=2:1.0000,3:1.0000|RCPU=31|UCPU=46|SCPU=0
TIME=20130917215759341|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIstop|MODE=SPCH|UCPU=0|SCPU=0
TIME=20130917215759341|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIepms|PD=0|BOS=580|SOS=720|EOS=-1|UCPU=625|SCPU=0
TIME=20130917215759341|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIendp|SRC=SWIep|BRGN=0|BTIM=580|MODE=SPCH|UCPU=625|SCPU=0
TIME=20130917215759372|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIepse|LUSED=1|LMAX=80|OMAX=-1|LFEAT=osr_swiep,ssm_u|LTIME=21625|UCPU=625|SCPU=0
TIME=20130917215759372|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIlise|SRC=SWIrec|LUSED=1|LMAX=80|OMAX=-1|LFEAT=osr_swirec,osr_rec_u,dtmf|LTIME=21625|UCPU=0|SCPU=0
TIME=20130917215759372|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=NUANtnat|TNAT=Nuance|UCPU=0|SCPU=0
TIME=20130917215759372|CHAN=01e33540-9a87-1231-50ad-005056a870bb|EVNT=SWIclnd|VALU=Session 01e33540-9a87-1231-50ad-005056a870bb ended|SRC=SWIrec|UCPU=0|SCPU=0

-------------------------------------------
And here's the Asterisk debug log:
[Sep 17 22:25:13] NOTICE[20941][C-00000006]: app_mrcprecog.c:1127 app_recog_exec: MRCPRecog() grammar: <?xml version="1.0"?>
<grammar xmlns="http://www.w3.org/2001/06/grammar" xml:lang="en-US" version="1.0" mode="voice" root="rootele">
<meta name="incompletetimeout" content="800"/>
<meta name="maxspeechtimeout" content="60000"/>
<rule id="rootele"><one-of><item></item><item>If you are calling about a power outage</item></one-of><ruleref special="GARBAGE"/></rule>
</grammar>
[Sep 17 22:25:13] NOTICE[20941][C-00000006]: app_mrcprecog.c:1144 app_recog_exec: MRCPRecog() options: p=default&i=any&t=26000&b=1&ct=0.20&gd=|
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option p: default
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option i: any
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option t: 26000
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option b: 1
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option ct: 0.20
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1025 mrcprecog_options_parse: Apply option gd: |
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: audio_queue.c:253 audio_queue_create: (ASR-10) Audio queue created
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: speech_channel.c:251 speech_channel_create: Created speech channel: Name=ASR-10, Type=RECOGNIZER, Codec=PCMU, Rate=8000
[Sep 17 22:25:13] NOTICE[20941][C-00000006]: app_unimrcp.c:122 unimrcp_log: Create MRCP Handle 0x700431c8 [speech-nuance5-mrcp2]
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_unimrcp.c:126 unimrcp_log: Create Channel ASR-10 <new>
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x70033f50;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x70033f50;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Receive App Request ASR-10 <new> [2]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Add MRCP Handle ASR-10 <new>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Dispatch App Request ASR-10 <new> [2]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCPv2ConnectionAgent] [0xb8009ce0;1;0]
[Sep 17 22:25:13] NOTICE[20346]: app_unimrcp.c:122 unimrcp_log: Add Control Channel ASR-10 <new@speechrecog>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Add Media Termination ASR-10 <new@media-tm>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Add Media Termination ASR-10 <new@rtp-tm>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MediaEngine] [0xb8005960;1;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Poller Wakeup [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCPv2ConnectionAgent] [0xb8009ce0;1;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x1ffb6b0;2;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x1ffb6b0;2;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Control Channel Added ASR-10 <new@speechrecog>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Process Message [MediaEngine] [0xb8005960;1;0]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Add Media Context ASR-10
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Media Termination Added ASR-10 <new@media-tm>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Media Termination Added ASR-10 <new@rtp-tm>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Send Offer ASR-10 <new> [c:1 a:1 v:0] to 10.12.40.115:5060
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Local SDP ASR-10 <new>
v=0
o=Asterisk 0 0 IN IP4 10.12.40.160
s=-
c=IN IP4 10.12.40.160
t=0 0
m=application 9 TCP/MRCPv2 1
a=setup:active
a=connection:new
a=resource:speechrecog
a=cmid:1
m=audio 4020 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=ptime:20
a=mid:1

[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_i_state] Status 0 INVITE sent
[Sep 17 22:25:13] NOTICE[20350]: app_unimrcp.c:122 unimrcp_log: SIP Call State ASR-10 [calling]
[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_r_invite] Status 200 OK
[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_i_state] Status 200 OK
[Sep 17 22:25:13] NOTICE[20350]: app_unimrcp.c:122 unimrcp_log: SIP Call State ASR-10 [ready]
[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Remote SDP ASR-10 <new>
v=0
o=- 1379456713 1379456713 IN IP4 10.12.40.115
s=Nuance MRCP session V2
c=IN IP4 10.12.40.115
t=0 0
a=session-timeout:120000
m=application 6075 TCP/MRCPv2 1
a=channel:4@speechrecog
a=cmid:1
a=connection:new
a=setup:passive
m=audio 7898 RTP/AVP 0 8 96 100
a=rtpmap:0 pcmu/8000
a=rtpmap:8 pcma/8000
a=rtpmap:96 l16/8000
a=rtpmap:100 telephone-event/8000
a=fmtp:100 0-15
a=recvonly
a=mid:1

[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x68029f40;1;0]
[Sep 17 22:25:13] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_i_active] Status 200 Call active
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x68029f40;1;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Receive Answer ASR-10 <new> [c:1 a:1 v:0] Status 200
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Modify Control Channel ASR-10 <4>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCPv2ConnectionAgent] [0xb800a190;1;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Modify Media Termination ASR-10 <4@rtp-tm>
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Poller Wakeup [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MediaEngine] [0xb8000d80;1;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCPv2ConnectionAgent] [0xb800a190;1;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] NOTICE[20347]: app_unimrcp.c:122 unimrcp_log: Established TCP/MRCPv2 Connection 10.12.40.160:52098 <-> 10.12.40.115:6075
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Add Control Channel <4@speechrecog> 10.12.40.160:52098 <-> 10.12.40.115:6075 [1]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x20a85e0;2;1]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x20a85e0;2;1]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Control Channel Modified ASR-10 <4@speechrecog>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Process Message [MediaEngine] [0xb8000d80;1;0]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Enable RTP Session 10.12.40.160:4020
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043b90 [5000]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [1000]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Create Null Audio Bridge ASR-10
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Open RTP Transmitter 10.12.40.160:4020 -> 10.12.40.115:7898
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Media Path ASR-10 Source->[PCMU/8000/1]->Bridge->[pcmu/8000/1]->Sink
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Media Termination Modified ASR-10 <4@rtp-tm>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App Response ASR-10 <4> [2] SUCCESS [0]
[Sep 17 22:25:13] DEBUG[20346]: app_mrcprecog.c:231 speech_on_channel_add: (ASR-10) speech_on_channel_add
[Sep 17 22:25:13] DEBUG[20346]: app_mrcprecog.c:250 speech_on_channel_add: (ASR-10) DTMF generator created
[Sep 17 22:25:13] NOTICE[20346]: app_mrcprecog.c:262 speech_on_channel_add: (ASR-10) Channel ready codec=PCMU, sample rate=8000
[Sep 17 22:25:13] DEBUG[20346]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) CLOSED ==> READY
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: speech_channel.c:489 speech_channel_open: (ASR-10) channel is ready
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1223 app_recog_exec: (ASR-10) Grammar delimiters: |
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:1236 app_recog_exec: (ASR-10) Determine grammar type: <?xml version="1.0"?>
<grammar xmlns="http://www.w3.org/2001/06/grammar" xml:lang="en-US" version="1.0" mode="voice" root="rootele">
<meta name="incompletetimeout" content="800"/>
<meta name="maxspeechtimeout" content="60000"/>
<rule id="rootele"><one-of><item></item><item>If you are calling about a power outage</item></one-of><ruleref special="GARBAGE"/></rule>
</grammar>
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_mrcprecog.c:695 recog_channel_load_grammar: (ASR-10) Loading grammar name=grammar-0, type=application/srgs+xml, data=<?xml version="1.0"?>
<grammar xmlns="http://www.w3.org/2001/06/grammar" xml:lang="en-US" version="1.0" mode="voice" root="rootele">
<meta name="incompletetimeout" content="800"/>
<meta name="maxspeechtimeout" content="60000"/>
<rule id="rootele"><one-of><item></item><item>If you are calling about a power outage</item></one-of><ruleref special="GARBAGE"/></rule>
</grammar>
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) READY ==> PROCESSING
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x700350b0;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x700350b0;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Receive App MRCP Request ASR-10 <4>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Send MRCP Request ASR-10 <4@speechrecog> [1]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCPv2ConnectionAgent] [0xb8009ce0;1;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Poller Wakeup [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCPv2ConnectionAgent] [0xb8009ce0;1;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Send MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [536 bytes]
MRCP/2.0 536 DEFINE-GRAMMAR 1
Channel-Identifier: 4@speechrecog
Content-Type: application/srgs+xml
Content-Id: grammar-0
Content-Length: 388

<?xml version="1.0"?>
<grammar xmlns="http://www.w3.org/2001/06/grammar" xml:lang="en-US" version="1.0" mode="voice" root="rootele">
<meta name="incompletetimeout" content="800"/>
<meta name="maxspeechtimeout" content="60000"/>
<rule id="rootele"><one-of><item></item><item>If you are calling about a power outage</item></one-of><ruleref special="GARBAGE"/></rule>
</grammar>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Signalled Descriptor [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Receive MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [65 bytes]
MRCP/2.0 65 1 200 COMPLETE
Channel-Identifier: 4@speechrecog

[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x20a8350;2;3]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x20a8350;2;3]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App MRCP Response ASR-10 <4>
[Sep 17 22:25:13] DEBUG[20346]: app_mrcprecog.c:850 recog_on_message_receive: (ASR-10) Grammar loaded
[Sep 17 22:25:13] DEBUG[20346]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) PROCESSING ==> READY
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] NOTICE[20941][C-00000006]: app_mrcprecog.c:1296 app_recog_exec: (ASR-10) Recognizing, enable DTMFs: 1, start input timers: 1
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: speech_channel.c:609 speech_channel_set_params: (ASR-10) Recognition-Timeout: 26000
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: speech_channel.c:609 speech_channel_set_params: (ASR-10) Confidence-Threshold: 0.20
[Sep 17 22:25:13] DEBUG[20941][C-00000006]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x700350b0;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x700350b0;4;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Receive App MRCP Request ASR-10 <4>
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Send MRCP Request ASR-10 <4@speechrecog> [2]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCPv2ConnectionAgent] [0xb8009f70;1;0]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Poller Wakeup [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCPv2ConnectionAgent] [0xb8009f70;1;0]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Send MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [235 bytes]
MRCP/2.0 235 RECOGNIZE 2
Channel-Identifier: 4@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Start-Input-Timers: true
Recognition-Timeout: 26000
Confidence-Threshold: 0.20
Content-Length: 17

session:grammar-0
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:4 o:640 ts:800]
[Sep 17 22:25:13] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [BYE] [76 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Signalled Descriptor [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Receive MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [68 bytes]
MRCP/2.0 68 2 200 IN-PROGRESS
Channel-Identifier: 4@speechrecog

[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x2705920;2;3]
[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x2705920;2;3]
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App MRCP Response ASR-10 <4>
[Sep 17 22:25:13] DEBUG[20346]: app_mrcprecog.c:809 recog_on_message_receive: (ASR-10) RECOGNIZE IN PROGRESS
[Sep 17 22:25:13] DEBUG[20346]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) READY ==> PROCESSING
[Sep 17 22:25:13] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:14] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [1000]
[Sep 17 22:25:14] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [2000]
[Sep 17 22:25:14] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Signalled Descriptor [MRCPv2ConnectionAgent]
[Sep 17 22:25:14] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Receive MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [132 bytes]
MRCP/2.0 132 START-OF-INPUT 2 IN-PROGRESS
Channel-Identifier: 4@speechrecog
Proxy-Sync-Id: 0-4@speechrecog
Input-Type: speech

[Sep 17 22:25:14] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x2706610;2;3]
[Sep 17 22:25:14] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:14] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x2706610;2;3]
[Sep 17 22:25:14] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App MRCP Event ASR-10 <4>
[Sep 17 22:25:14] DEBUG[20346]: app_mrcprecog.c:869 recog_on_message_receive: (ASR-10) START OF INPUT
[Sep 17 22:25:14] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:15] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [2000]
[Sep 17 22:25:15] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [3000]
[Sep 17 22:25:16] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [3000]
[Sep 17 22:25:16] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [4000]
[Sep 17 22:25:17] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [4000]
[Sep 17 22:25:17] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [5000]
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043b90 [5000]
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:245 o:39200 ts:39600]
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [52 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043b90 [10000]
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [5000]
[Sep 17 22:25:18] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [6000]
[Sep 17 22:25:19] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [6000]
[Sep 17 22:25:19] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [7000]
[Sep 17 22:25:20] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [7000]
[Sep 17 22:25:20] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [8000]
[Sep 17 22:25:21] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [8000]
[Sep 17 22:25:21] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [9000]
[Sep 17 22:25:22] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [9000]
[Sep 17 22:25:22] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [10000]
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043b90 [10000]
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:495 o:79200 ts:79600]
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [52 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043b90 [15000]
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [10000]
[Sep 17 22:25:23] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [11000]
[Sep 17 22:25:24] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [11000]
[Sep 17 22:25:24] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [12000]
[Sep 17 22:25:25] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [12000]
[Sep 17 22:25:25] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [13000]
[Sep 17 22:25:26] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [13000]
[Sep 17 22:25:26] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [14000]
[Sep 17 22:25:27] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [14000]
[Sep 17 22:25:27] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [15000]
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043b90 [15000]
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:745 o:119200 ts:119600]
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [52 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043b90 [20000]
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [15000]
[Sep 17 22:25:28] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [16000]
[Sep 17 22:25:29] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [16000]
[Sep 17 22:25:29] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [17000]
[Sep 17 22:25:30] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [17000]
[Sep 17 22:25:30] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [18000]
[Sep 17 22:25:31] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [18000]
[Sep 17 22:25:31] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [19000]
[Sep 17 22:25:32] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [19000]
[Sep 17 22:25:32] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [20000]
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043b90 [20000]
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:995 o:159200 ts:159600]
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [52 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043b90 [25000]
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [20000]
[Sep 17 22:25:33] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [21000]
[Sep 17 22:25:34] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Timer Elapsed 0x70043bc0 [21000]
[Sep 17 22:25:34] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Set Timer 0x70043bc0 [22000]
[Sep 17 22:25:34] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Signalled Descriptor [MRCPv2ConnectionAgent]
[Sep 17 22:25:34] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Receive MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [115 bytes]
MRCP/2.0 115 RECOGNITION-COMPLETE 2 COMPLETE
Channel-Identifier: 4@speechrecog
Completion-Cause: 001 no-match

[Sep 17 22:25:34] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x2706610;2;3]
[Sep 17 22:25:34] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:34] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x2706610;2;3]
[Sep 17 22:25:34] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App MRCP Event ASR-10 <4>
[Sep 17 22:25:34] DEBUG[20346]: app_mrcprecog.c:865 recog_on_message_receive: (ASR-10) RECOGNITION COMPLETE, Completion-Cause: 001
[Sep 17 22:25:34] DEBUG[20346]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) PROCESSING ==> READY
[Sep 17 22:25:34] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:35] DEBUG[20941][C-00000006]: app_mrcprecog.c:472 recog_channel_get_results: (ASR-10) Completion-Cause: 001
[Sep 17 22:25:35] DEBUG[20941][C-00000006]: speech_channel.c:333 speech_channel_destroy: Destroy speech channel: Name=ASR-10, Type=RECOGNIZER, Codec=PCMU, Rate=8000
[Sep 17 22:25:35] DEBUG[20941][C-00000006]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x70032a70;4;0]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x70032a70;4;0]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Receive App Request ASR-10 <4> [1]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Dispatch App Request ASR-10 <4> [1]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Terminate Session ASR-10 <4>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Remove Control Channel ASR-10 <4>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCPv2ConnectionAgent] [0xb8009f70;1;0]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Poller Wakeup [MRCPv2ConnectionAgent]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCPv2ConnectionAgent] [0xb8009f70;1;0]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Remove Control Channel <4@speechrecog> [0]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Close TCP/MRCPv2 Connection 10.12.40.160:52098 <-> 10.12.40.115:6075
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Subtract Media Termination ASR-10 <4@media-tm>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Subtract Media Termination ASR-10 <4@rtp-tm>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MediaEngine] [0xb8005960;1;0]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x2706610;2;2]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:35] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCPv2ConnectionAgent]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x2706610;2;2]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Control Channel Removed ASR-10 <4@speechrecog>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:35] DEBUG[20941][C-00000006]: speech_channel.c:347 speech_channel_destroy: (ASR-10) Waiting for MRCP session to terminate
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Process Message [MediaEngine] [0xb8005960;1;0]
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Destroy Audio Bridge ASR-10
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Close RTP Transmitter 10.12.40.160:4020 -> 10.12.40.115:7898 [s:1078 o:172480]
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Remove Media Context ASR-10
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Remove RTP Session 10.12.40.160:4020
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Kill Timer 0x70043b90 [25000]
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Kill Timer 0x70043bc0 [22000]
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Generate RTCP SR [ssrc:3412148535 s:1078 o:172480 ts:172800]
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Send Compound RTCP Packet [BYE] [76 bytes] 10.12.40.160:4021 -> 10.12.40.115:7899
[Sep 17 22:25:35] DEBUG[20348]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x94000e90;3;0]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Media Termination Subtracted ASR-10 <4@media-tm>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Media Termination Subtracted ASR-10 <4@rtp-tm>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:35] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_r_bye] Status 200 OK
[Sep 17 22:25:35] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Receive SIP Event [nua_i_state] Status 200 to BYE
[Sep 17 22:25:35] NOTICE[20350]: app_unimrcp.c:122 unimrcp_log: SIP Call State ASR-10 [terminated]
[Sep 17 22:25:35] DEBUG[20350]: app_unimrcp.c:126 unimrcp_log: Signal Message to [MRCP Client] [0x68029f40;1;1]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Process Message [MRCP Client] [0x68029f40;1;1]
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Session Terminated ASR-10 <4>
[Sep 17 22:25:35] NOTICE[20346]: app_unimrcp.c:122 unimrcp_log: Destroy TCP/MRCPv2 Connection 10.12.40.160:52098 <-> 10.12.40.115:6075
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Remove MRCP Handle ASR-10 <4>
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Raise App Response ASR-10 <4> [1] SUCCESS [0]
[Sep 17 22:25:35] DEBUG[20346]: app_mrcprecog.c:200 speech_on_session_terminate: (ASR-10) speech_on_session_terminate
[Sep 17 22:25:35] DEBUG[20346]: app_mrcprecog.c:204 speech_on_session_terminate: (ASR-10) DTMF generator destroyed
[Sep 17 22:25:35] DEBUG[20346]: app_mrcprecog.c:209 speech_on_session_terminate: (ASR-10) Destroying MRCP session
[Sep 17 22:25:35] NOTICE[20346]: app_unimrcp.c:122 unimrcp_log: Destroy MRCP Handle ASR-10
[Sep 17 22:25:35] DEBUG[20346]: speech_channel.c:106 speech_channel_set_state_unlocked: (ASR-10) READY ==> CLOSED
[Sep 17 22:25:35] DEBUG[20346]: app_unimrcp.c:126 unimrcp_log: Wait for Messages [MRCP Client]
[Sep 17 22:25:35] DEBUG[20941][C-00000006]: audio_queue.c:197 audio_queue_destroy: (ASR-10) Audio queue destroyed
[Sep 17 22:25:35] NOTICE[20941][C-00000006]: app_mrcprecog.c:1087 mrcprecog_exit: MRCPRecog() exiting status: OK on SIP/10.12.40.90-00000006

Arsen Chaloyan

unread,

Sep 25, 2013, 9:03:31 PM9/25/13

to UniMRCP

Hi Robby,

My understanding is you use the speech recognition capabilities of Asterisk to test an IVR interface. In other words, MRCPRecog() is supposed to recognize IVR prompts streamed from the remote party. If I read your message wrong, please correct me.

Anyway, to deal with long utterances, the first thing one needs to set is a longer Recognition-Timeout, what you already did. The other timeout which may have a significant impact on the result is the Speech-Incomplete-Timeout. And I'd guess this is what you still need to alter. For your tests, try to set the Speech-Incomplete-Timeout to, let's say, 3 sec, so the utterance is not faulty broken up.

Running MRCPRecog() with the options t=26000&sint=3000 against NSS, I have the time to breathe :) and can easily pass a 20sec window still getting a match in the end.

--
You received this message because you are subscribed to the Google Groups "UniMRCP" group.
To unsubscribe from this group and stop receiving emails from it, send an email to unimrcp+u...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

--
Arsen Chaloyan
Author of UniMRCP
http://www.unimrcp.org

Raymond Menard

unread,

Sep 25, 2013, 10:54:30 PM9/25/13

to uni...@googlegroups.com

Hi Robby

The 20 sec timeouts that you see in the Nuance log (inet.timeoutDownload=20000;inet.timeoutIO=20000;inet.timeoutOpen=20000) apply to the grammar load as they appear on the EVNT=SWIgrld trace record. They have nothing to do with the actual recognition. It is a coincidence that the prompt is 20-sec long.

The actual recognition was terminated by the 800 millisecond speech incomplete timeout specified in the actual grammar (<meta name="incompletetimeout" content="800"/>). The 001-nomatch returned by NSS is due to the low confidence score from the recognizer as indicated in the EVNT=SWIrcnd trace record (see below).

incompletetimeout

Controls the length of a period of silence after callers have spoken to conclude that they

finished. This timer is also known as the “end of speech” timeout (or more correctly, the

after end of speech timeout).

As the 77 confidence score value (i.e. 77 on 1000 or 0.077) is below the 0.2 confidence score threshold, NSS returns “001- No match”.

As indicated in the Asterisk log, the confidence score threshold is set to .2 on the RECOGNIZE request

[Sep 17 22:25:13] DEBUG[20347]: app_unimrcp.c:126 unimrcp_log: Send MRCPv2 Stream 10.12.40.160:52098 <-> 10.12.40.115:6075 [235 bytes]
MRCP/2.0 235 RECOGNIZE 2
Channel-Identifier: 4@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Start-Input-Timers: true
Recognition-Timeout: 26000
Confidence-Threshold: 0.20
Content-Length: 17

session:grammar-0

So it appears that recognition actually worked. The words “If you are calling about a power outage” were recognized as indicated by the RSLT, RAWT and SPOK fields below.

Trace record broken one field per line for readability and commenting

TIME=20130917215759341|

CHAN=01e33540-9a87-1231-50ad-005056a870bb|

EVNT=SWIrcnd|

RSTT=lowconf| ç===== low confidence score indication

RENR=prun|

ENDR=itimeout| ç===== recognition terminated by normal end of speech (incompletetimout)

NBST=1|

RSLT={SWI_literal:If you are calling about a power outage}|

RAWT=If you are calling about a power outage|

SPOK=If you are calling about a power outage|

GRMR=GURI0|

KEYS=<SWI_confidence conf="0">0</SWI_confidence>|

CONF=77| ç===== actual low confidence score value (range 0 to 999)

Reply all

Reply to author

Forward

0 new messages