MRCPRecog problem with NOINPUT timeout

486 views

Skip to first unread message

assanta

unread,

Mar 17, 2010, 7:48:35 AM3/17/10

to UniMRCP

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)

Here 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")

[Mar 17 11:42:40] DEBUG[2153]: pbx.c:1844 pbx_extension_helper:
Launching 'MRCPRecog'
-- Executing [999999999@default2:3] MRCPRecog("SIP/Santa-
b73adc28", "<?xml version=\"1.0\" encoding=\"ISO-8859-1\"?><grammar
xmlns=\"http://www.w3.org/2001/06/grammar\" xml:lang=\"en-US\" 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=5&sct=2&sint=3") in new stack
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|p=speech-loquendo-mrcp1|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|i=any|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|t=5000|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|f=|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|b=0|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|nit=5|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|sct=2|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4767 app_recog_exec:
Option=|sint=3|
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4880 app_recog_exec:
Profile to use: speech-loquendo-mrcp1
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4883 app_recog_exec:
Grammar to recognize with: <?xml version="1.0" encoding="ISO-8859-1"?
><grammar xmlns="http://www.w3.org/2001/06/grammar" xml:lang="en-US"
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>
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4889 app_recog_exec:
Recognition timeout: 5000
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4892 app_recog_exec:
Barge-in: 0
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4934 app_recog_exec:
Speech incomplete timeout : 3
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4937 app_recog_exec:
Speech complete timeout: 2
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4943 app_recog_exec: No-
input timeout: 5
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4964 app_recog_exec:
DTMF enable: 1
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:934 audio_queue_create:
(ASR-56) audio queue created
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1827
speech_channel_create: Created speech channel: Name=ASR-56,
Type=RECOGNIZER, Codec=PCMU, Rate=8000
[Mar 17 11:42:40] NOTICE[2153]: app_unimrcp.c:4141 unimrcp_log: Create
MRCP Handle 0xb7301918 [speech-loquendo-mrcp1]
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:4144 unimrcp_log: Create
Channel 0xb7301918 <new>
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MRCP Client] [4;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [4;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive App Request 0xb7301918 <new> [2]
[Mar 17 11:42:40] NOTICE[28633]: app_unimrcp.c:4141 unimrcp_log:
Create RTSP Handle 0xb7303920
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Add
MRCP Handle 0xb7301918
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Dispatch Application Request 0xb7301918 <new> [2]
[Mar 17 11:42:40] NOTICE[28633]: app_unimrcp.c:4141 unimrcp_log: Add
Control Channel 0xb7301918 <new@speechrecog>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Add
RTP Termination 0xb7301918 <new>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MPF Engine] [1;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MPF Engine] [1;0]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Add
Context
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Add
Termination
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Add
Termination
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [3;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: On
Termination Add 0xb7301918 <new>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: On
Termination Add 0xb7301918 <new>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Send
Offer 0xb7301918 <new> [c:0 a:1 v:0] to 100.100.100.2:8554
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [UniRTSP Agent] [1;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Poller Wakeup [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Message [UniRTSP Agent] [1;0]
[Mar 17 11:42:40] NOTICE[28636]: app_unimrcp.c:4141 unimrcp_log:
Established RTSP Connection 100.100.100.1:36930 <-> 100.100.100.2:8554
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Add
RTSP Handle 0xb7303920
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Send
RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [372 bytes]
SETUP rtsp://100.100.100.2:8554/recognizer RTSP/1.0
CSeq: 1
Transport: RTP/AVP;unicast;client_port=10112-10113
Content-Type: application/sdp
Content-Length: 202

v=0
o=Asterisk 0 0 IN IP4 100.100.100.1
s=-
c=IN IP4 100.100.100.1
t=0 0
m=audio 10112 RTP/AVP 0 8 96
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:96 L16/8000
a=sendonly
a=ptime:60

[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Push
RTSP Request to In-Progress Queue 0xb7303920 <new> CSeq:1
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [206
bytes]
RTSP/1.0 200 OK
CSeq: 1
Session: 2...@100.100.100.2:554
Transport: RTP/
AVP;unicast;destination=100.100.100.2;client_port=10112;server_port=10000
Content-Type: application/sdp
Content-Length: 176

[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Truncated RTSP Message [206]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [176
bytes]
v=0
o=- 3477811360 3477811360 IN IP4 100.100.100.2
s=Loquendo MRCPv1 Media Server
c=IN IP4 100.100.100.2
t=3477811360 0
m=audio 10000 RTP/AVP 0
a=rtpmap:0 PCMU/8000

[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Parsed
RTSP Message [176]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Pop In-
Progress RTSP Request 0xb7303920 CSeq:1
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Add
RTSP Session 0xb7303920 <2...@100.100.100.2:554>
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [1;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive Answer 0xb7301918 <2...@100.100.100.2:554> [c:0 a:1 v:0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Modify
Termination 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MPF Engine] [1;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MPF Engine] [1;0]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Enable
RTP Session 100.100.100.1:10112
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [5000]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [1000]
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Create
Null Audio Bridge
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Open
RTP Transmitter 100.100.100.1:10112 -> 100.100.100.2:10000
[Mar 17 11:42:40] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Source-
>[PCMU/8000/1]->Bridge->[PCMU/8000/1]->Sink
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [3;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: On
Termination Modify 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Raise
App Response 0xb7301918 <2...@100.100.100.2:554> [2] SUCCESS [0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:2350
speech_on_channel_add: speech_on_channel_add
[Mar 17 11:42:40] NOTICE[28633]: app_unimrcp.c:2359
speech_on_channel_add: (ASR-56) DTMF generator created
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:2386
speech_on_channel_add: (ASR-56) RECOGNIZER channel is ready, codec =
PCMU, sample rate = 8000
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) CLOSED ==> READY
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:2142 speech_channel_open:
(ASR-56) channel is ready
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1650
speech_channel_set_param: (ASR-56) param = recognition-timeout, val =
5000
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1650
speech_channel_set_param: (ASR-56) param = speech-incomplete-timeout,
val = 3
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1650
speech_channel_set_param: (ASR-56) param = speech-complete-timeout,
val = 2
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1650
speech_channel_set_param: (ASR-56) param = no-input-timeout, val = 5
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:5087 app_recog_exec:
Grammar type is: 3
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:3581
recog_channel_load_grammar: (ASR-56) Loading grammar ASR-56, data = <?
xml version="1.0" encoding="ISO-8859-1"?><grammar xmlns="http://
www.w3.org/2001/06/grammar" xml:lang="en-US" 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>
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) READY ==> PROCESSING
[Mar 17 11:42:40] DEBUG[2153]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MRCP Client] [4;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [4;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive App MRCP Request 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Send
MRCP Request 0xb7301918 <2...@100.100.100.2:554@speechrecog> [1]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [UniRTSP Agent] [1;0]
[Mar 17 11:42:40] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Poller Wakeup [UniRTSP Agent]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Message [UniRTSP Agent] [1;0]
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Send
RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [513 bytes]
ANNOUNCE rtsp://100.100.100.2:8554/recognizer RTSP/1.0
CSeq: 2
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 357

DEFINE-GRAMMAR 1 MRCP/1.0
Content-Type: application/srgs+xml
Content-Id: ASR-56
Content-Length: 251

<?xml version="1.0" encoding="ISO-8859-1"?><grammar xmlns="http://
www.w3.org/2001/06/grammar" xml:lang="en-US" 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>
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Push
RTSP Request to In-Progress Queue 0xb7303920 <2...@100.100.100.2:554>
CSeq:2
[Mar 17 11:42:40] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [114
bytes]
RTSP/1.0 200 OK
CSeq: 2
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 58

[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Truncated RTSP Message [114]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [58
bytes]
MRCP/1.0 1 200 COMPLETE
Completion-Cause: 000 success

[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Parsed
RTSP Message [58]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Pop In-
Progress RTSP Request 0xb7303920 CSeq:2
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [1;2]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Raise
App MRCP Response 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:3782
recog_on_message_receive: (ASR-56) grammar loaded
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) PROCESSING ==> READY
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:41] NOTICE[2153]: app_unimrcp.c:5288 app_recog_exec:
Recognizing
[Mar 17 11:42:41] DEBUG[2153]: app_unimrcp.c:3365
recog_channel_set_params: (ASR-56) speech-complete-timeout: 2
[Mar 17 11:42:41] DEBUG[2153]: app_unimrcp.c:3365
recog_channel_set_params: (ASR-56) recognition-timeout: 5000
[Mar 17 11:42:41] DEBUG[2153]: app_unimrcp.c:3365
recog_channel_set_params: (ASR-56) speech-incomplete-timeout: 3
[Mar 17 11:42:41] DEBUG[2153]: app_unimrcp.c:3365
recog_channel_set_params: (ASR-56) no-input-timeout: 5
[Mar 17 11:42:41] DEBUG[2153]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MRCP Client] [4;0]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [4;0]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive App MRCP Request 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Send
MRCP Request 0xb7301918 <2...@100.100.100.2:554@speechrecog> [2]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [UniRTSP Agent] [1;0]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Poller Wakeup [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Message [UniRTSP Agent] [1;0]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Send
RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [349 bytes]
ANNOUNCE rtsp://100.100.100.2:8554/recognizer RTSP/1.0
CSeq: 3
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 193

RECOGNIZE 2 MRCP/1.0
No-Input-Timeout: 5
Recognition-Timeout: 5000
Speech-Complete-Timeout: 2
Speech-Incomplete-Timeout: 3
Content-Type: text/uri-list
Content-Length: 14

session:ASR-56
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Push
RTSP Request to In-Progress Queue 0xb7303920 <2...@100.100.100.2:554>
CSeq:3
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:5 o:2400 ts:2560]
[Mar 17 11:42:41] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:42:41] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [BYE] [104 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [114
bytes]
RTSP/1.0 200 OK
CSeq: 3
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 30

[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Parsed
RTSP Message [30]
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Pop In-
Progress RTSP Request 0xb7303920 CSeq:3
[Mar 17 11:42:41] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [1;2]
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Raise
App MRCP Response 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:3741
recog_on_message_receive: (ASR-56) RECOGNIZE IN PROGRESS
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) READY ==> PROCESSING
[Mar 17 11:42:41] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:41] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [1000]
[Mar 17 11:42:41] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [2000]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [156
bytes]
ANNOUNCE rtsp://100.100.100.2:8554/recognizer RTSP/1.0
CSeq: 1
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 340

[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Truncated RTSP Message [156]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [340
bytes]
RECOGNITION-COMPLETE 2 COMPLETE MRCP/1.0
Proxy-Sync-Id: A4DA02F000000039
Completion-Cause: 002 no-input-timeout
Content-Type: application/nlsml+xml
Content-Length: 165

<?xml version="1.0" encoding="UTF-8"?>
<result grammar="">
<interpretation grammar="">
<instance/>
<input>
<noinput/>
</input>
</interpretation>
</result>
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Parsed
RTSP Message [340]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Send
RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [62 bytes]
RTSP/1.0 200 OK
CSeq: 1
Session: 2...@100.100.100.2:554

[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [1;2]
[Mar 17 11:42:42] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Raise
App MRCP Event 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:3797
recog_on_message_receive: (ASR-56) RECOGNITION COMPLETE, Completion-
Cause: 002
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:3804
recog_on_message_receive: (ASR-56) Recognition result is not null-
terminated. Appending null terminator
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:3094
recog_channel_set_results: (ASR-56) result:

<?xml version="1.0" encoding="UTF-8"?>
<result grammar="">
<interpretation grammar="">
<instance/>
<input>
<noinput/>
</input>
</interpretation>
</result>
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) PROCESSING ==> READY
[Mar 17 11:42:42] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:42:42] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:9200]
[Mar 17 11:42:42] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:42:42] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [BYE] [104 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:42:42] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 84 bytes
[Mar 17 11:42:42] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [2000]
[Mar 17 11:42:42] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [3000]
[Mar 17 11:42:43] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [3000]
[Mar 17 11:42:43] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [4000]
[Mar 17 11:42:44] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [4000]
[Mar 17 11:42:44] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [5000]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301df0 [5000]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:39600]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [80 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [10000]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [5000]
[Mar 17 11:42:45] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [6000]
[Mar 17 11:42:46] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [6000]
[Mar 17 11:42:46] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [7000]
[Mar 17 11:42:47] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 84 bytes
[Mar 17 11:42:47] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [7000]
[Mar 17 11:42:47] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [8000]
[Mar 17 11:42:48] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [8000]
[Mar 17 11:42:48] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [9000]
[Mar 17 11:42:49] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [9000]
[Mar 17 11:42:49] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [10000]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301df0 [10000]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:79600]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [80 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [15000]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [10000]
[Mar 17 11:42:50] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [11000]
[Mar 17 11:42:51] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [11000]
[Mar 17 11:42:51] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [12000]
[Mar 17 11:42:51] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 118 bytes
[Mar 17 11:42:52] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [12000]
[Mar 17 11:42:52] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [13000]
[Mar 17 11:42:52] DEBUG[2153]: rtp.c:1250 ast_rtp_read: Forcing Marker
bit, because SSRC has changed
[Mar 17 11:42:52] NOTICE[2153]: rtp.c:830 process_rfc3389: Comfort
noise support incomplete in Asterisk (RFC 3389). Please turn off on
client if possible. Client IP: 100.100.100.14
[Mar 17 11:42:53] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 84 bytes
[Mar 17 11:42:53] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [13000]
[Mar 17 11:42:53] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [14000]
[Mar 17 11:42:54] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [14000]
[Mar 17 11:42:54] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [15000]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301df0 [15000]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:119600]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [80 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [20000]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [15000]
[Mar 17 11:42:55] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [16000]
[Mar 17 11:42:56] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [16000]
[Mar 17 11:42:56] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [17000]
[Mar 17 11:42:57] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [17000]
[Mar 17 11:42:57] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [18000]
[Mar 17 11:42:58] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 84 bytes
[Mar 17 11:42:58] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [18000]
[Mar 17 11:42:58] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [19000]
[Mar 17 11:42:59] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [19000]
[Mar 17 11:42:59] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [20000]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301df0 [20000]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:159600]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [80 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [25000]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [20000]
[Mar 17 11:43:00] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [21000]
[Mar 17 11:43:01] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [21000]
[Mar 17 11:43:01] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [22000]
[Mar 17 11:43:02] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [22000]
[Mar 17 11:43:02] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [23000]
[Mar 17 11:43:03] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 84 bytes
[Mar 17 11:43:03] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [23000]
[Mar 17 11:43:03] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [24000]
[Mar 17 11:43:04] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [24000]
[Mar 17 11:43:04] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [25000]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301df0 [25000]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:199600]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [80 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301df0 [30000]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [25000]
[Mar 17 11:43:05] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [26000]
[Mar 17 11:43:05] DEBUG[2153]: rtp.c:923 ast_rtcp_read: Got RTCP
report of 118 bytes
[Mar 17 11:43:06] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Timer
Elapsed 0xb7301e08 [26000]
[Mar 17 11:43:06] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Set
Timer 0xb7301e08 [27000]
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:2952
recog_channel_check_results: (ASR-56) SUCCESS, have result
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:3129
recog_channel_get_results: (ASR-56) result:

<?xml version="1.0" encoding="UTF-8"?>
<result grammar="">
<interpretation grammar="">
<instance/>
<input>
<noinput/>
</input>
</interpretation>
</result>
[Mar 17 11:43:07] NOTICE[2153]: app_unimrcp.c:5407 app_recog_exec:
Result=|<?xml version="1.0" encoding="UTF-8"?>
<result grammar="">
<interpretation grammar="">
<instance/>
<input>
<noinput/>
</input>
</interpretation>
</result>|
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:3701
recog_channel_unload_grammar: (ASR-56) Unloading grammar ASR-56
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:1970
speech_channel_destroy: Destroying speech channel: Name=ASR-56,
Type=RECOGNIZER, Codec=PCMU, Rate=8000
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MRCP Client] [4;0]
[Mar 17 11:43:07] DEBUG[2153]: app_unimrcp.c:1988
speech_channel_destroy: (ASR-56) Waiting for MRCP session to terminate
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [4;0]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive App Request 0xb7301918 <2...@100.100.100.2:554> [1]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Dispatch Application Request 0xb7301918 <2...@100.100.100.2:554> [1]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Terminate Session 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Subtract Channel Termination 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Subtract Termination 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [MPF Engine] [1;0]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Signal
Message to [UniRTSP Agent] [1;0]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:43:07] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Poller Wakeup [UniRTSP Agent]
[Mar 17 11:43:07] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Message [UniRTSP Agent] [1;0]
[Mar 17 11:43:07] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Send
RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [103 bytes]
TEARDOWN rtsp://100.100.100.2:8554/recognizer RTSP/1.0
CSeq: 4
Session: 2...@100.100.100.2:554

[Mar 17 11:43:07] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Push
RTSP Request to In-Progress Queue 0xb7303920 <2...@100.100.100.2:554>
CSeq:4
[Mar 17 11:43:07] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MPF Engine] [1;0]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Destroy Audio Bridge
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Close
RTP Transmitter 100.100.100.1:10112 -> 100.100.100.2:10000 [s:12 o:
5760]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Subtract Termination
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log:
Subtract Termination
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Remove
Context
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Remove
RTP Session 100.100.100.1:10112
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Kill
Timer 0xb7301df0 [30000]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4147 unimrcp_log: Kill
Timer 0xb7301e08 [27000]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP SR [ssrc:3321925806 s:12 o:5760 ts:209280]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log:
Generate RTCP RR [ssrc:0 last_seq:0 j:0 lost:1 frac:0]
[Mar 17 11:43:07] DEBUG[28635]: app_unimrcp.c:4144 unimrcp_log: Send
Compound RTCP Packet [BYE] [104 bytes] 100.100.100.1:10113 ->
100.100.100.2:10001
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [3;0]
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: On
Termination Subtract 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: On
Termination Subtract 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:07] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log:
Process Signalled Descriptor [UniRTSP Agent]
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log:
Receive RTSP Stream 100.100.100.1:36930 <-> 100.100.100.2:8554 [62
bytes]
RTSP/1.0 200 OK
CSeq: 4
Session: 2...@100.100.100.2:554

[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Parsed
RTSP Message [62]
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Pop In-
Progress RTSP Request 0xb7303920 CSeq:4
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Remove
RTSP Session 0xb7303920 <2...@100.100.100.2:554>
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Remove
RTSP Handle 0xb7303920
[Mar 17 11:43:08] NOTICE[28636]: app_unimrcp.c:4141 unimrcp_log:
Destroy RTSP Handle 0xb7303920
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4144 unimrcp_log: Close
RTSP Connection 100.100.100.1:36930 <-> 100.100.100.2:8554
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log:
Process Message [MRCP Client] [1;1]
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log:
Receive Terminate Response 0xb7301918 <2...@100.100.100.2:554>
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Remove
MRCP Handle 0xb7301918
[Mar 17 11:43:08] NOTICE[28636]: app_unimrcp.c:4141 unimrcp_log:
Destroy RTSP Connection 100.100.100.1:36930 <-> 100.100.100.2:8554
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:4144 unimrcp_log: Raise
App Response 0xb7301918 <2...@100.100.100.2:554> [1] SUCCESS [0]
[Mar 17 11:43:08] DEBUG[28636]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [UniRTSP Agent]
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:2319
speech_on_session_terminate: speech_on_session_terminate
[Mar 17 11:43:08] NOTICE[28633]: app_unimrcp.c:2323
speech_on_session_terminate: (ASR-56) DTMF generator destroyed
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:2328
speech_on_session_terminate: (ASR-56) Destroying MRCP session
[Mar 17 11:43:08] NOTICE[28633]: app_unimrcp.c:4141 unimrcp_log:
Destroy MRCP Handle 0xb7301918
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:1672
speech_channel_set_state_unlocked: (ASR-56) READY ==> CLOSED
[Mar 17 11:43:08] DEBUG[28633]: app_unimrcp.c:4147 unimrcp_log: Wait
for Messages [MRCP Client]
[Mar 17 11:43:08] DEBUG[2153]: app_unimrcp.c:881 audio_queue_destroy:
(ASR-56) audio queue destroyed
[Mar 17 11:43:08] NOTICE[2153]: app_unimrcp.c:2013
speech_channel_destroy: (ASR-56) Audio queue destroyed
[Mar 17 11:43:08] DEBUG[2153]: app_unimrcp.c:2055
speech_channel_destroy: Destroyed speech channel complete

Here is 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)

11:42:41.514 [09274bb0] [Flow.Dump]
[CDispatcher::SendResponse()] SessionId:[2...@100.100.100.2:554]; MRCP
Request Message sent: [RTSP/1.0 200 OK
CSeq: 3
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 30

MRCP/1.0 2 200 IN-PROGRESS

]. Header length:[114]; total length:[144]. R318
11:42:41.938 [09274bb0] [Flow.Dump]
[CDispatcher::SendRequest()] SessionId:[2...@100.100.100.2:554]; MRCP
Request Message sent: [ANNOUNCE rtsp://100.100.100.2:8554/recognizer
RTSP/1.0
CSeq: 1
Session: 2...@100.100.100.2:554
Content-Type: application/mrcp
Content-Length: 340

RECOGNITION-COMPLETE 2 COMPLETE MRCP/1.0
Proxy-Sync-Id: A4DA02F000000039
Completion-Cause: 002 no-input-timeout
Content-Type: application/nlsml+xml
Content-Length: 165

<?xml version="1.0" encoding="UTF-8"?>
<result grammar="">
<interpretation grammar="">
<instance/>
<input>
<noinput/>
</input>
</interpretation>
</result>]. Header length:[156]; total length:[496]. R422
11:42:42.115 [0fd10bb0] [Flow.Dump]
[CDispatcher::ReceiveFunction()] SessionId:[2...@100.100.100.2:554];
MRCP Response Message received: [RTSP/1.0 200 OK
CSeq: 1
Session: 2...@100.100.100.2:554

]. Header length:[62]; total length:[62]. R2293
11:43:07.159 [0fd10bb0] [Flow.Dump]
[CDispatcher::ReceiveFunction()] SessionId:[2...@100.100.100.2:554];
MRCP Request Message received: [TEARDOWN rtsp://100.100.100.2:8554/recognizer
RTSP/1.0
CSeq: 4
Session: 2...@100.100.100.2:554

]. Header length:[103]; total length:[103]. R2286
11:43:07.957 [0fd10bb0] [Flow.Dump]
[CDispatcher::SendResponse()] SessionId:[2...@100.100.100.2:554]; MRCP
Request Message sent: [RTSP/1.0 200 OK
CSeq: 4
Session: 2...@100.100.100.2:554

]. Header length:[62]; total length:[62]. R318
11:43:08.054 [0fd10bb0] [Flow.Dump]
[CDispatcher::ReceiveFunction()] Client Connection Closed (Exit Code:
[0]); remote address: [100.100.100.2]; local address: [100.100.100.2];
socket handle: [99afc848]. R2185

Maybe you prefer I open an ISSUE?

ASSANTA

Arsen Chaloyan

unread,

Mar 18, 2010, 2:06:08 AM3/18/10

to uni...@googlegroups.com

Hi Assanta,

The description of your problem seems to be clear. Perhaps it'd require some time to dig into. Being busy with other activities, I'd prefer to have this in the issue tracker for now. So, I or Derik will process it when possible.

--
You received this message because you are subscribed to the Google Groups "UniMRCP" group.
To post to this group, send email to uni...@googlegroups.com.
To unsubscribe from this group, send email to unimrcp+u...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/unimrcp?hl=en.