MRCP sessions terminated

[Klaudyna Witczak]

Hello,

I have a problem with too many mrcp sessions - I think. Maybe problem exists somewhere else. I use FreeSwitch (as MRCP client) and connect it to MRCP server on another machine (in the same lan). Here's what I got:

log from mrcp server:

Mar  3 13:48:32 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:487829 [NOTICE] Add Session <c2da3ed87c1e11eb>
Mar  3 13:48:32 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:487849 [INFO]   Receive Offer 0x7f39ec03a1d8 <c2da3ed87c1e11eb> [c:1 a:1 v:0]
Mar  3 13:48:32 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:488058 [INFO]   Add Pending Control Channel <c2da3ed87c1e11eb@speechrecog> [1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492304 [INFO]   Enable RTP Session 0.0.0.0:10852
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492373 [INFO]   Open RTP Receiver 0.0.0.0:10852 <- 192.168.113.142:10328 playout [50 ms] bounds [0 - 600 ms] adaptive [1] skew detection [1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492407 [INFO]   Media Path 0x7f39ec03a1d8 Source->[PCMU/8000/1]->Decoder->[LPCM/8000/1]->Bridge->[LPCM/8000/1]->Sink
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492475 [INFO]   [c2da3ed87c1e11eb] Current count of open recognition channels: 5
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492486 [INFO]   Send Answer 0x7f39ec03a1d8 <c2da3ed87c1e11eb> [c:1 a:1 v:0] Status OK
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:492496 [INFO]   Local SDP 0x7f39ec03a1d8 <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: v=0
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: o=UniMRCPServer 0 0 IN IP4 192.168.113.140
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: s=-
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: c=IN IP4 192.168.113.140
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: t=0 0
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: m=application 12544 TCP/MRCPv2 1
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=setup:passive
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=connection:existing
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=channel:c2da3ed87c1e11eb@speechrecog
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=cmid:1
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: m=audio 10852 RTP/AVP 0
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=rtpmap:0 PCMU/8000
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=recvonly
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: a=mid:1
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]:
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493427 [INFO]   Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493436 [NOTICE] SIP Call State 0x7f39ec03a1d8 [completed]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493844 [INFO]   Receive SIP Event [nua_i_ack] Status 200 OK [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493855 [INFO]   Receive SIP Event [nua_i_state] Status 200 OK [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493858 [NOTICE] SIP Call State 0x7f39ec03a1d8 [ready]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:493860 [INFO]   Receive SIP Event [nua_i_active] Status 200 Call active [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498529 [INFO]   Receive SIP Event [nua_i_bye] Status 200 Session Terminated [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498543 [INFO]   Receive SIP Event [nua_i_state] Status 200 Session Terminated [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498546 [NOTICE] SIP Call State 0x7f39ec03a1d8 [terminated]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498565 [INFO]   Receive SIP Event [nua_i_terminated] Status 200 Session Terminated [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498583 [INFO]   Deactivate Session 0x7f39ec03a1d8 <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498591 [INFO]   Terminate Session 0x7f39ec03a1d8 <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498620 [INFO]   Remove Pending Control Channel <c2da3ed87c1e11eb@speechrecog> [0]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498648 [INFO]   [new] Received total 0 ms of audio in 0 requests.
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:498659 [INFO]   [c2da3ed87c1e11eb] Current count of open recognition channels: 4
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:502375 [INFO]   Close RTP Receiver 0.0.0.0:10852 <- 192.168.113.142:10328 [r:0 l:0 j:0 p:50 d:0 i:0]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:502386 [INFO]   Remove RTP Session 0.0.0.0:10852
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:502447 [NOTICE] Remove Session <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:502452 [INFO]   Session Terminated 0x7f39ec03a1d8 <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:48:32:502477 [NOTICE] Destroy Session <c2da3ed87c1e11eb>
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:49:26:452132 [INFO]   Receive SIP Event [nua_i_invite] Status 100 Trying [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:49:26:452161 [INFO]   Receive SIP Event [nua_i_state] Status 100 Trying [SIP-Agent-1]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:49:26:452167 [NOTICE] SIP Call State 0x7f39ec0381c8 [received]
Mar  3 13:49:26 sltapp020 docker-asr-mrcp-service[324698]: 2021-03-03 12:49:26:452204 [INFO]   Remote SDP 0x7f39ec0381c8 <7bbfa28c7c1d11eb>

log from FreeSwitch:

2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fc5a00009a0;3;0]
2021-03-03 12:48:20.952576 [DEBUG] mrcp_client_session.c:985 (ASR-980) Media Termination Modified ASR-980 <c2da3ed87c1e11eb@rtp-tm>
2021-03-03 12:48:20.952576 [INFO] mrcp_client_session.c:455 (ASR-980) Raise App Response ASR-980 <c2da3ed87c1e11eb> [2] SUCCESS [0]
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1900 (ASR-980) RECOGNIZER channel is ready, codec = LPCM, sample rate = 8000
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1584 (ASR-980) CLOSED ==> READY
2021-03-03 12:48:20.952576 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1062 (ASR-980) channel is ready
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = start-input-timers, val = false
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] switch_core_media_bug.c:962 Attaching BUG to sofia/external/+48725558512@192.168.113.132
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = ai.lekta.asr.id, val = dictation
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = ai.lekta.asr.context_phrase, val = transcribe
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = start-input-timers, val = false
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = no-input-timeout, val = 10000
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = speech-complete-timeout, val = 2000
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1465 (ASR-980) param = recognition-timeout, val = 30000
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:3201 (ASR-980) grammar = yes_or_no, name =
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:3226 (ASR-980) Grammar is inside file
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:3290 (ASR-980) grammar is application/srgs
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:2361 (ASR-980) Loading grammar bbfb78f2-7c1e-11eb-81d1-eb4d75125173, data = #ABNF 1.0;
a91d3cde-7c1e-11eb-81c3-eb4d75125173 language pl-pl;
a91d3cde-7c1e-11eb-81c3-eb4d75125173 mode voice;
a91d3cde-7c1e-11eb-81c3-eb4d75125173 root $root;
a91d3cde-7c1e-11eb-81c3-eb4d75125173 tag-format <semantics/1.0-literals>;
a91d3cde-7c1e-11eb-81c3-eb4d75125173
a91d3cde-7c1e-11eb-81c3-eb4d75125173 $root=
a91d3cde-7c1e-11eb-81c3-eb4d75125173    tak |
a91d3cde-7c1e-11eb-81c3-eb4d75125173    owszem |
a91d3cde-7c1e-11eb-81c3-eb4d75125173    nie;
a91d3cde-7c1e-11eb-81c3-eb4d75125173
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1584 (ASR-980) READY ==> PROCESSING
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fc5c0149a90;4;0]
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fc5c0149a90;4;0]
2021-03-03 12:48:20.952576 [INFO] mrcp_client_session.c:392 (ASR-980) Receive App MRCP Request ASR-980 <c2da3ed87c1e11eb>
2021-03-03 12:48:20.952576 [INFO] mrcp_client_session.c:622 (ASR-980) Send MRCP Request ASR-980 <c2da3ed87c1e11eb@speechrecog> [1]
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:265 () Signal Message to [MRCPv2ConnectionAgent] [0x7fc5d800f750;1;0]
2021-03-03 12:48:20.952576 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
2021-03-03 12:48:20.952576 [DEBUG] apt_poller_task.c:261 () Process Poller Wakeup [MRCPv2ConnectionAgent]
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:337 () Process Message [MRCPv2ConnectionAgent] [0x7fc5d800f750;1;0]
2021-03-03 12:48:20.952576 [WARNING] mrcp_client_connection.c:518 (ASR-980) Null MRCPv2 Connection <c2da3ed87c1e11eb@speechrecog>
2021-03-03 12:48:20.952576 [WARNING] mrcp_client_connection.c:477 (ASR-980) Cancel MRCP Request <c2da3ed87c1e11eb@speechrecog> [1]
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fc5d42c17d0;2;3]
2021-03-03 12:48:20.952576 [DEBUG] apt_poller_task.c:251 () Wait for Messages [MRCPv2ConnectionAgent]
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:337 () Process Message [MRCP Client] [0x7fc5d42c17d0;2;3]
2021-03-03 12:48:20.952576 [INFO] mrcp_client_session.c:500 (ASR-980) Raise App MRCP Response ASR-980 <c2da3ed87c1e11eb>
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:3661 (ASR-980) grammar failed to load, status code = 407
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:1584 (ASR-980) PROCESSING ==> ERROR
2021-03-03 12:48:20.952576 [DEBUG] apt_consumer_task.c:141 () Wait for Messages [MRCP Client]
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] switch_ivr_async.c:5086 Error loading Grammar
2021-03-03 12:48:20.952576 [DEBUG] apt_task.c:265 () Signal Message to [MRCP Client] [0x7fc5c00e5c50;4;0]
a91d3cde-7c1e-11eb-81c3-eb4d75125173 2021-03-03 12:48:20.952576 [DEBUG] mod_unimrcp.c:930 (ASR-980) Waiting for MRCP session to terminate

Effect is that I can't say something to ASR because there's no mrcp session with asr (it is terminated). How to solve it? Is it possible that I have limits for this type of sesions?

[Arsen Chaloyan]

Hello Klaudyna,

There is nothing that would catch my attention in the provided logs.

> Effect is that I can't say something to ASR because there's no mrcp session with asr (it is terminated). How to solve it? Is it possible that I have limits for this type of sesions?

You should check why the ASR session is terminated. There must be a WARN statement logged.

--
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.
To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/dfbda122-b3d0-4c7e-9a04-1010be848423o%40googlegroups.com.

--

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

[klaudyn...@gmail.com]

Hi Arsen,

thanks for quick reply :) Now we changed max-session-count to 1000 (from 100) and for now it's working without error loading grammar. Interesting, because we didn't generate so much sessions.

I have another question on this -  force-new-connection=true means that if there's no TCP connection (it is destroyed/terminated/whatever) between MRCP server and MRCP client, MRCP should force creation new connection on other ports - right or am I wrong?

Very thanks for your help and for MRCP :)

Klaudyna

[Lewis Bergman]

I had a similar problem. I had a lot of issues trying to get uniMRCP to work with Freeswitch. More accurately, I had nearly zero trouble installing the uniMRCP server and testing it. mod_unimrcp and the freeswitch config gave me fits. Somewhere I made a mistake in config and I didnt (and still don't) know enough about Freeswitch to read the logs. 

For me, I went back to the uniMRCP guides step by step making sure to check off each step doggedly. I set up the dialplan tests as instructed and at the end of that process and all have worked perfectly. Not that that is what you should do, but sometimes if you are at a total loss, the beginning is a good place to start again.

Now using mod_unimrcp to do things like transcribe voicemails is another matter. There seems to be no ready built way to do that.

--

Lewis Bergman

[Arsen Chaloyan]

Hi Klaudyna,

On Tue, Mar 9, 2021 at 3:41 AM klaudyn...@gmail.com <klaudyn...@gmail.com> wrote:

Hi Arsen,

thanks for quick reply :) Now we changed max-session-count to 1000 (from 100) and for now it's working without error loading grammar. Interesting, because we didn't generate so much sessions.

This would typically indicate that the sessions are not properly released, which is likely caused by the implementation of your plugin.

 

I have another question on this -  force-new-connection=true means that if there's no TCP connection (it is destroyed/terminated/whatever) between MRCP server and MRCP client, MRCP should force creation new connection on other ports - right or am I wrong?

See my response here.

To view this discussion on the web visit https://groups.google.com/d/msgid/unimrcp/934fcf81-5565-4bf1-8556-66b502335f76n%40googlegroups.com.