Peer disconnected--how to handle?

[GoogleCodeExporter]

Hi Arsen,

Here is an abnormal situation which was not handled... The log file will be
attached. We got a peer disconnect:

TCP/MRCPv2 Peer Disconnected 10.10.10.65:4685 <-> 10.10.10.69:6075 
[mrcp_client_connection:514]

after sending a GET-PARAMS. At that point, the  function
on_message_receive() was called by the UniMRCP dispatcher, with the
start_line.message_type set to MRCP_MESSAGE_TYPE_REQUEST, which we do not
handle (just log). I stopped the applcation with a <CTRL-C> and it stopped
correctly. I am not sure if MRCP_MESSAGE_TYPE_REQUEST was the right message
type in these circumstances. If it was, can you please explain briefly how
to handle it.

I used r1394.

Thanks a lot.   

Original issue reported on code.google.com by Curat...@gmail.com on 12 Jan 2010 at 4:20

Attachments:

• Peer-Disonnected.txt

[GoogleCodeExporter]

Hi Vlad,

I've checked the log, but it seems incomplete. I see your application received
several MRCP responses, but I see no "Receive MRCPv2 Stream" and similar 
entries.
If you made any changes in the code, please revert them at least for now, then 
we
will see how to beatify those logs.
Also what do you think, if peer indeed was disconnected or this was a false 
event?
Perhaps, network capture would be helpful too.

Original comment by achalo...@gmail.com on 12 Jan 2010 at 11:56

[GoogleCodeExporter]

Hi Arsen,

There are two erroneous behaviors. One occurs in BOTH r1380 AND r1394 and is 
captured
in the log file "Cannot-parse-mrcp-version-in-request-line.txt" for r1380 only. 
Keep
in mind that the problem happens in both releases but not every time I want. I 
have a
log file only for r1380. Also note that in r1380 I set MRCP_STREAM_BUFFER_SIZE 
to
16384. When this problem strikes, I have to kill the Command Prompt window 
where the
test application was running, using the Task Manager. In r1380 the application
executed several cycles before it got stuck. In r1394 it was getting stuck in 
the
first cycle and there were more parse error messages similar to "Cannot parse
mrcp-version in request-line".

The second problem is captured in the log files
"Unexpected-MRCP_MESSAGE_TYPE_REQUEST*.*". This happens in r1394 only. In this 
case,
I can interrupt the application using <CTRL-C> and it terminates apparently 
normally:
the client sends a BYE and the server sends an OK back. The common 
manifestation is
that the application receives an unexpected MRCP_MESSAGE_TYPE_REQUEST as you 
can see
in the log file. There are two variations of this problem: in one case there is 
no
"peer disconnect", in the other case there is a "peer disconnect" statement in 
the
log file. The WireShark log corresponds to the latter case. Note that in the 
server
log file I can see that the response to the last GET-PARAMS request was sent!!!

Let me know if need more data, although the various behaviors do not seem very
consistent and easy to reproduce. For the time being I will go back to r1380. 
This
seems to work best for me :-(.

Thanks a lot. 

Original comment by Curat...@gmail.com on 13 Jan 2010 at 4:20

Attachments:

• Cannot-parse-mrcp-version-in-request-line.txt
• Unexpected-MRCP_MESSAGE_TYPE_REQUEST-Test-1.txt
• Unexpected-MRCP_MESSAGE_TYPE_REQUEST-Test-2.txt
• Unexpected-MRCP_MESSAGE_TYPE_REQUEST-and-Peer-Disconnected-Test-3.txt
• Unexpected-MRCP_MESSAGE_TYPE_REQUEST-and-Peer-Disconnected-Test-4.txt
• Peer-Disconnect.pcap

[GoogleCodeExporter]

Here is a new log file. I pasted the log statement from the server log file 
which
shows their response to the last GET-PARAMS request. The response-line seems 
valid. I
bet you this has something to do with your "in-line" processing of the server
messages :-(. It seems to always happen when the server response is relatively 
long
(this one has the vendor specific parameters).

Thanks a lot.

Original comment by Curat...@gmail.com on 13 Jan 2010 at 5:38

Attachments:

• Cannot-parse-request-id-in-request-line-and-server-resonse.txt

[GoogleCodeExporter]

Hi Vlad,

I've tried many many things during the day, but unfortunately, neither 
managed to replicate the same strange behavior nor figured out what it ever 
could be.
Reading the description, I suspect something ran in endless loop, but looking 
at the
code, I've got absolutely no answers.

I extracted TCP stream (Follow TCP Stream) from Wireshark capture and passed 
exactly
the same stream to the parser... messages were successfully parsed.
I tried to recreate the same sequence of SET-PARAMS and GET-PARAMS requests 
using umc
application and Nuance several dozen of times with 1Kb, 4Kb, 16 Kb read 
buffers, all
worked without any problem.

In the meantime, I noticed the following strange request in the capture you 
attached

MRCP/2.0 235 SET-PARAMS 7
Channel-Identifier: 1001@speechrecog
Vendor-Specific-Parameters:
confidencelevel=500,sensitivity=0.500,speedvsaccuracy=0.789,timeout=1000,swirec_
application_name=UniMRCP,swirec_phoneme_lookahead_beam=-50

MRCP/2.0 237 7 404 COMPLETE
Vendor-Specific-Parameters:
confidencelevel=500,sensitivity=0.500,speedvsaccuracy=0.789,timeout=1000,swirec_
application_name=UniMRCP,swirec_phoneme_lookahead_beam=-50
Channel-Identifier: 1001@speechrecog

How could you use ',' as a separator, there should be ';' instead. It seems API
doesn't provide such an option at all, unless you modify something in the stack.
Also "Receive MRCPv2 Stream", "Truncated Message" "Scroll Stream" log entries 
might
be really helpful in this case.

BTW, I've committed umc related changes to SVN, so we could use the same code 
base.
Please checkout a fresh copy at r1397 and try to replicate the same with umc
application. It executes very similar sequence of commands.
Update umcscenarios.xml in order to use the following command
> run params

Looking forward to have this issue resolved.

Original comment by achalo...@gmail.com on 13 Jan 2010 at 9:31

[GoogleCodeExporter]

Thanks, Arsen and sorry for the trouble. I know that it is hard to debug such 
issues.
Just a quick clarification, in case I do not have the time to do what you said 
today.

The comma separator was used on purpose, to see that the server handles an 
incorrect
request correctly, which it does as you may have seen (it returns 404). 

We need to create abnormal situations because they would expose weaknesses in 
our code.

Cheers.

Original comment by Curat...@gmail.com on 14 Jan 2010 at 12:00

[GoogleCodeExporter]

Hi Arsen,

I ran a "umc" test using this "scenario" in umcscenarios.xml:

<scenario name="params" class="Params" profile="MRCPv2-Default">
    <resource-discovery enable="0"/>
    <termination enable="1">
    </termination>
</scenario>

I am not sure if this is the right way to create a "scenario" for parameters
handling. If not, please show me. I added the "termination" element to make it 
look
more similar to my app., not for other reasons. The parsing did choke when it 
got to
the Vendor-Specific. I will upload the log file.

Thanks a lot.

Original comment by Curat...@gmail.com on 14 Jan 2010 at 2:53

Attachments:

• unimrcpclient-0.log

[GoogleCodeExporter]

I also ran my application, built using r1397 and got exactly the same result as 
"umc"
did, which is good news. The log file will be uploaded.

Cheers.

Original comment by Curat...@gmail.com on 14 Jan 2010 at 3:06

Attachments:

• Set-Get-Params-Failure-Using-r1397.txt

[GoogleCodeExporter]

Hi Vlad,

Thanks for the update. I believe we will finally narrow down the issue within a 
few
attempts.

I've analyzed the logs and indeed weird things happened there 
(unimrcpclient-0.log).
Let's jump to the part where problems started to appear.
2010-01-13 18:41:06:179348 [INFO]   Receive MRCPv2 Stream 10.10.10.65:3732 <->
10.10.10.69:6075 [1023 bytes]
MRCP/2.0 3223 6 200 COMPLETE
Channel-Identifier: 1011@speechrecog
Logging-Tag: 
Fetch-Timeout: 10000
Vendor-Specific-Parameters:
server.osrspeechrecog.result.mediatype=application/x-vnd.speechworks.emma+xml;st
rictconfidencelevel=1;mrcpv=2.06
Vendor-Specific-Parameters: confidencelevel=500
Vendor-Specific-Parameters: sensitivity=0.500
Vendor-Specific-Parameters: speedvsaccuracy=0.789
Vendor-Specific-Parameters: timeout=1000
Vendor-Specific-Parameters: completetimeout=1000
Vendor-Specific-Parameters: incompletetimeout=2000
Vendor-Specific-Parameters: swirec_nbest_list_length=5
Vendor-Specific-Parameters: swirec_max_cpu_time=20000
Vendor-Specific-Parameters: server.osrspeechrecog.result.sendnomatch=false
Vendor-Specific-Parameters: swirec_tenant_name=Nuance
Vendor-Specific-Parameters: swirec_company_name=Nuance
Vendor-Specific-Parameters: swirec_application_name=UniMRCP
Vendor-Specific-Parameters: maxspeechtimeout=-1
Vendor-Specific-Parameters: swirec_barge_in_mode=normal
Vendor-Specific-Para

Well, message indeed should be segmented here as message length was 3223 bytes, 
while
we read only 1023 bytes.
I see the next entry in the logs is
2010-01-13 18:41:06:179348 [INFO]   Receive MRCPv2 Stream 10.10.10.65:3732 <->
10.10.10.69:6075 [20 bytes]

which is strange enough. Where did those 20 bytes come from, when our buffer is 
about
1KB. Moreover, every "Receive MRCPv2 Stream" should follow with either
"Parsed MRCP Message" or "Truncated MRCP Message" or "Failed to Parse MRCP 
Message"
entries. Obviously for the previous case there should be "Truncated MRCP 
Message" and
"Scroll MRCP Stream" thereafter. I think you could commented those logs out, 
which is
not that bad. But if you commented actual call for apt_text_stream_scroll() 
function
either, yes, this would result exactly with what we have now.

Please make sure you have no modifications in mrcp_stream.c, unless I'm missing
something very obvious here.
Thanks for all your help getting project better.

Original comment by achalo...@gmail.com on 14 Jan 2010 at 6:21

[GoogleCodeExporter]

The results of the previous test were vitiated by an inadvertent local 
modification
of the UniMRCP source code. The various manifestations of this issue reported 
earlier
are not reproducible anymore. 

Arsen already addressed the unexpected MRCP_MESSAGE_TYPE_REQUEST and will make 
the
TCP/IP buffer size configurable.

Original comment by Curat...@gmail.com on 17 Jan 2010 at 1:16

[GoogleCodeExporter]

Thanks for the update, Vlad.

From my side, I admit investigations made in the scope of this issue helped to 
fix a
potential issue in r1401. Also I provided an option to configure buffer size in
r1402, which might be useful for others too.

Original comment by achalo...@gmail.com on 17 Jan 2010 at 7:51

• Changed state: Fixed