MRCPRecog problem with NOINPUT timeout

[GoogleCodeExporter]

What version of the product are you using? On what operating system?
Asterisk 1.4
RHEL 3.9 Update 9
LoquendoSS 7.0
uni-ast-package-0.2.0 (with unimrcp-0.10.0 and new revision 1578)

Please provide any additional information below.
I have a problem with the NOINPUT timeout in the MRCPRecog 
It sames like MRCP don't realize and continues with the recognition, I 
have to do any kind of noise (or hangup) so that MRCP realize. 

Here the dialplan
(the logs are with nit=5&sct=2&sint=3 because at first I thought there 
were seconds, but then I realized there were milliseconds, the test 
has the same result) 
exten => 914895004,3,MRCPRecog(<?xml version=\\\"1.0\\\" encoding=\\ 
\"ISO-8859-1\\\"?><grammar xmlns=\\\"http://www.w3.org/2001/06/grammar\ 
\\" xml:lang=\\\"es-ES\\\" version=\\\"1.0\\\" mode=\\\"voice\\\" root= 
\\\"digit\\\"><rule id=\\\"digit\\\"><one-of><item>one</ 
item><item>two</item><item>three</item></one-of></rule></ 
grammar>,p=speech-loquendo- 
mrcp1&i=any&t=5000&f=&b=0&nit=5000&sct=2000&sint=3000) 

I attach the Asterisk log 
(we can see unimrcp receive the Loquendo no-input-timeout at 11:42:42 
but unimrcp continues with the recognition until I make a noise at 
11:43:07, the different I can see betwen the first and the second 
recognition is that in the first one this appears 
"recog_channel_set_results" and "speech_channel_set_state_unlocked" 
and in the second one this appears "recog_channel_check_results" and 
"recog_channel_get_results" and "recog_channel_unload_grammar") 

I also attach the Loquendo log: 
(We can see that betwen the OK receive of the noinput and the TERDOWN 
receive is a lot of time waiting MRCP) 

Regards
Assanta

Original issue reported on code.google.com by assantas...@gmail.com on 18 Mar 2010 at 10:20

Attachments:

• AsteriskLog.txt
• LoquendoLog.txt

[GoogleCodeExporter]

Original comment by achalo...@gmail.com on 18 Mar 2010 at 11:28

• Added labels: Component-Asterisk, OpSys-Linux, Priority-Medium

[GoogleCodeExporter]

Hi Assanta,

I'm not sure why this is happening to you. :-) Are you making use of RTCP - not 
that
I would know if it would help? I'm using Nuance and it works for me. I get back 
a
"Completion-Cause: 002", which is no-input timeout. See my traces below. 
Perhaps your
MRCP server doesn't send the correct MRCP response back? I suppose a wireshark 
trace
of this may be needed to confirm this.

Arsen: any ideas?

Kind regards,
Derik

/var/log/asterisk/messages
----------------------------------
...
3279:[Mar 18 14:58:39] DEBUG[28714] app_unimrcp.c: (ASR-50) RECOGNIZE IN 
PROGRESS
3280:[Mar 18 14:58:39] DEBUG[28714] app_unimrcp.c: (ASR-50) READY ==> PROCESSING
3281:[Mar 18 14:58:39] DEBUG[28714] app_unimrcp.c: Wait for Messages [MRCP 
Client]
3448:[Mar 18 14:58:40] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19368 
[1000]
3449:[Mar 18 14:58:40] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19368 [2000]
3657:[Mar 18 14:58:41] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19368 
[2000]
3658:[Mar 18 14:58:41] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19368 [3000]
3839:[Mar 18 14:58:42] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19368 
[3000]
3840:[Mar 18 14:58:42] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19368 [4000]
4057:[Mar 18 14:58:43] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19368 
[4000]
4058:[Mar 18 14:58:43] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19368 [5000]
4205:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19350 
[5000]
4206:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Generate RTCP SR 
[ssrc:3391576878
s:239 o:38240 ts:39680]
4207:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Send Compound RTCP Packet [52
bytes] 10.211.30.88:4101 -> 10.217.30.2:7893
4208:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19350 [10000]
4209:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Timer Elapsed 0xaea19368 
[5000]
4210:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Set Timer 0xaea19368 [6000]
4262:[Mar 18 14:58:44] DEBUG[28715] app_unimrcp.c: Process Signalled Descriptor
[TCP/MRCPv2 Agent]
4263:[Mar 18 14:58:44] DEBUG[28715] app_unimrcp.c: Receive MRCPv2 Stream
10.211.30.88:38126 <-> 10.217.30.2:6075 [124 bytes]
4269:[Mar 18 14:58:44] DEBUG[28715] app_unimrcp.c: Parsed MRCP Message [124]
4270:[Mar 18 14:58:44] DEBUG[28715] app_unimrcp.c: Signal Message to [MRCP 
Client] [2;3]
4271:[Mar 18 14:58:44] DEBUG[28715] app_unimrcp.c: Wait for Messages 
[TCP/MRCPv2 Agent]
4272:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: Process Message [MRCP 
Client] [2;3]
4273:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: Raise App MRCP Event 
0xaea18d98 <28>
4274:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: (ASR-50) RECOGNITION 
COMPLETE,
Completion-Cause: 002
4275:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: (ASR-50) result:
4278:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: (ASR-50) No result
4279:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: (ASR-50) PROCESSING ==> READY
4280:[Mar 18 14:58:44] DEBUG[28714] app_unimrcp.c: Wait for Messages [MRCP 
Client]
4285:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Generate RTCP SR 
[ssrc:3391576878
s:260 o:41600 ts:43040]
4286:[Mar 18 14:58:44] DEBUG[28716] app_unimrcp.c: Send Compound RTCP Packet 
[BYE]
[76 bytes] 10.211.30.88:4101 -> 10.217.30.2:7893
4287:[Mar 18 14:58:44] DEBUG[4449] app_unimrcp.c: (ASR-50) SUCCESS, have result
4288:[Mar 18 14:58:44] DEBUG[4449] app_unimrcp.c: (ASR-50) result:
4291:[Mar 18 14:58:44] NOTICE[4449] app_unimrcp.c: Result=|Completion-Cause: 
002|
4292:[Mar 18 14:58:44] DEBUG[4449] app_unimrcp.c: (ASR-50) Unloading grammar 
ASR-50
4293:[Mar 18 14:58:44] DEBUG[4449] app_unimrcp.c: Destroying speech channel:
Name=ASR-50, Type=RECOGNIZER, Codec=PCMA, Rate=8000
...

extensions.conf
----------------
exten =>
1001,n,MRCPRecog(http://127.0.0.1/grammar/digits.grxml,p=default&i=any&t=30000&b
=1&sl=0.8&nit=5000)

Original comment by thirion...@gmail.com on 18 Mar 2010 at 1:08

[GoogleCodeExporter]

Thanks for the analysis, Derik.

I think everything is clear and right with message flow. 
Although there is a small difference in RECOGNITION-COMPLETE messages your 
servers
generate in case of noinput, it still should cause that delay.
BTW, I'd suggest to check completion-cause first and only then proceed with the 
body
and set the results.

Now the question is why recognition loop in app_unimrcp didn't end (break), when
state was changed from PROCESSING to READY. Probably Assanta could add a few 
traces
between the following lines.

while (((waitres = ast_waitfor(chan, 100)) >= 0))

if (recog_channel_check_results(schannel) == 0) {

Just my thoughts made analyzing the code and outputs.

Original comment by achalo...@gmail.com on 18 Mar 2010 at 2:37

[GoogleCodeExporter]

Hi

The first important thing I see, Derik is using MRCPv2 and I'm using MRCPv1, 
also I 
see differents in some lines:

I have a Line that has no Derik
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:1672 
speech_channel_set_state_unlocked: (ASR-56) PROCESSING ==> READY

Derik has a line that I haven't until I do another noise after the NOINPUT (I 
think 
here is the clue)
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:2952 recog_channel_check_results: 
(ASR-
56) SUCCESS, have result

Arsen, I'll be out until monday, but I'll send you the traces on monday. It 
seems 
that no break from "while (((waitres = ast_waitfor(chan, 100)) >= 0)"

Thanks
Assanta

Original comment by assantas...@gmail.com on 18 Mar 2010 at 6:01

[GoogleCodeExporter]

Hi Assanta,

I don't think this issue depends on protocol version in use.

> It seems that no break from "while (((waitres = ast_waitfor(chan, 100)) >= 0)"
This is exactly what I suspected.

> Derik has a line that I haven't until I do another noise after the NOINPUT (I 
think
here is the clue)

ast_waitfor() is released as soon as there is a new frame to process. That's why
noise or any other activity will do that.

Strange thing is there is 100 msec timeout and ast_waitfor() should be released 
in
100 msec even if there is no activity. Why it doesn't happen? I don't know...

Anyway, take your time and provide more details when possible.

Original comment by achalo...@gmail.com on 18 Mar 2010 at 6:17

[GoogleCodeExporter]

Hi Assanta & Arsen,

That seems like very good analysis. Perhaps on my end it releases from 
ast_waitfor
due to a different version of Asterisk being used. I am using 1.6.1.17 with 
libss7
and Digium cards for the E1 lines.

Kind regards,
Derik

Original comment by thirion...@gmail.com on 19 Mar 2010 at 7:03

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

Hi

I attach the while code with log and the asterisk log

Really seems like is always in the while, but the "waitres" has a correct value
Is any process inside the while that init this value? ast_frfree?

Any Ideas?

I continue testing

Assanta

Original comment by assantas...@gmail.com on 22 Mar 2010 at 12:49

Attachments:

• AsteriskLogTest.txt
• unimrcpWhileLog.txt

[GoogleCodeExporter]

[deleted comment]

[GoogleCodeExporter]

Hi

another test, maybe you could see somethimg new

I'm a litle lost with this

Assanta

Original comment by assantas...@gmail.com on 22 Mar 2010 at 3:46

Attachments:

• unimrcpWhileLog2.txt
• AsteriskLogTest2.txt

[GoogleCodeExporter]

Hi Assanta,

I've just got a chance to look at the attached logs. Everything seems clear now 
and I
think I can reproduce it in a couple of minutes if needed.
Before proceeding any further, I'd like to mention that you may easily 
workaround
this problem by disabling silence suppression (VAD) on the SIP phone or device 
you're
using with Asterisk. Asterisk itself doesn't support discontinuous RTP 
transmission,
so I guess it makes sense to disable it anyway.
Back to the issue, it's clear that channel state should be checked even in case 
there
is no activity (audio,video or any other frames) from the end user and ast_wait 
is
released due to elapsed timeout.

The problem is here
[Mar 22 15:49:53] NOTICE[27031]: app_unimrcp.c:5343 app_recog_exec: 
step1.2=|100|
[Mar 22 15:49:53] NOTICE[27031]: app_unimrcp.c:5387 app_recog_exec: step6.1=|10|

The following check should be considered
if (schannel->state != SPEECH_CHANNEL_PROCESSING) {
   break
}

and it'll break the recognition loop.

You may try to fix it on your then we will see.

Original comment by achalo...@gmail.com on 24 Mar 2010 at 2:04

• Changed state: Accepted

[GoogleCodeExporter]

Hi Arsen & Assanta,

Thanks for the check/code. I've submitted the changes to the trunk.

Assanta, please update to the latest version and retest.

Kind regards,
Derik

Original comment by thirion...@gmail.com on 24 Mar 2010 at 2:22

[GoogleCodeExporter]

Hi

I was testing my changes, that seemed to be working ok

- check_result inside the while:

    while (((waitres = ast_waitfor(chan, 100)) >= 0)) {

        if (recog_channel_check_results(schannel) == 0) {
            break;
        }

- and status=1 in the "start_of_input" of the "recog_channel_check_results":

    else if (r->start_of_input){
        ast_log(LOG_DEBUG, "(%s) SUCCESS, start of input\n", schannel->name);
        status = 1;
            }

I've tested also your changes and works fine, so I'll use yours :-)

Thanks
Assanta

Original comment by assantas...@gmail.com on 24 Mar 2010 at 3:29

[GoogleCodeExporter]

Hi Assanta,

I'm glad it works. All credit goes to Arsen as it was his suggestion and 
analysis - 
I've merely implemented that in trunk. So well done Arsen!

Kind regards,
Derik

Original comment by thirion...@gmail.com on 24 Mar 2010 at 7:06

• Changed state: Verified

[GoogleCodeExporter]

No problem, glad to see you on the board, Derik.

And thanks for the issue report, Assanta.

Best regards,
Arsen

Original comment by achalo...@gmail.com on 24 Mar 2010 at 7:22