Closed scgm11 closed 6 years ago
achaloyan
commented
6 years ago Not sure what the exact reason of the overflow is in your case, but generally this happens when an IN-PROGRESS response to the RECOGNIZE request arrives late. The longer is the delay, the higher are chances for overflow, since audio frames written from Asterisk are being accumulated in the meantime.
sfgeorge
commented
6 years ago I wanted to share one other case in which this happens.
I often encounter this when the audio being received for recognition is coming with extreme jitter. This seems to cause the buffer to overrun. In this case, I find the buffer overruns several seconds after successful IN-PROGRESS establishment (roughly after 18 seconds with 8000 bit-rate pcmu).
In my case, this has been caused by a carrier delivering RTP to us with wildly different timestamps...
If you are encountering this issue after several seconds of recognition, I believe the best resolution is to verify if the affected calls are experiencing severe jitter, and if so, to report and resolve with your upstream provider.
@achaloyan While my issue is definitely related to intolerable jitter, I'm still surprised how it managed to fill the buffer. We have a max-playout-delay of 200ms, within a buffer buffer than I understand to hold up to 2 seconds of audio for 8000 bitrate audio.
We have the following jitter settings in mrcp.conf:
; --- Jitter buffer settings ---
playout-delay = 50
max-playout-delay = 200
; --- RTP settings ---
ptime = 20
codecs = PCMU PCMA L16/96/8000 telephone-event/101/8000
; --- RTCP settings ---
rtcp = 0Thinking from the perspective of Asterisk/MRCP client, there is no RTP jitter buffer employed for speech recognition in the MRCP leg. Please note that the RTP stream received on the inbound SIP leg is processed and de-jitterred by Asterisk. So, the palyout delay specified in mrcp.conf has no impact in this case, and is actually used for speech synthesis only.
lazarevdmitriy
commented
1 year ago Hi. I have a similar problem.
Asterisk is waiting for the recognized data from the mrcp server. The Mrcp server crashes at this moment. Asterisk continues to wait for a response for 8 minutes, then displays the message "Audio queue overflow"
[Aug 26 22:22:43] NOTICE[14060]: src/mrcp_client_session.c:479 Raise App Event ASR-26 <71f17a26257411ed> [0]
[Aug 26 22:28:49] WARNING[27829][C-00000012]: audio_queue.c:327 audio_queue_write: (ASR-26) Audio queue overflow!All this time, two udp connections open at the time of recognition continue to hang on the asterisk (оn ports 28012 and 28013).
# netstat -lnpu | grep 10.2.0.27
udp 0 0 10.2.0.27:8061 0.0.0.0:* 22688/asterisk
udp 0 0 10.2.0.27:8062 0.0.0.0:* 22688/asterisk
udp 0 0 10.2.0.27:28012 0.0.0.0:* 22688/asterisk
udp 0 0 10.2.0.27:28013 0.0.0.0:* 22688/asterisk What can be done?
See the short log below. And full log here https://pastebin.com/GRRbXRz9
[Aug 26 22:22:37] NOTICE[14063]: src/mrcp_sofiasip_client_agent.c:617 Receive SIP Event [nua_i_active] Status 200 Call active [asr]
[Aug 26 22:22:37] NOTICE[14060]: src/mrcp_client_session.c:149 Receive Answer ASR-26 <new> [c:1 a:1 v:0] Status 200
[Aug 26 22:22:37] NOTICE[14061]: src/mrcp_client_connection.c:346 Established TCP/MRCPv2 Connection 10.2.0.27:39342 <-> 10.2.0.23:11544
[Aug 26 22:22:37] NOTICE[14061]: src/mrcp_client_connection.c:456 Add Control Channel <71f17a26257411ed@speechrecog> 10.2.0.27:39342 <-> 10.2.0.23:11544 [1]
[Aug 26 22:22:37] NOTICE[14062]: src/mpf_rtp_stream.c:331 Enable RTP Session 10.2.0.27:28032
[Aug 26 22:22:37] NOTICE[14062]: src/mpf_rtp_stream.c:921 Open RTP Transmitter 10.2.0.27:28032 -> 10.2.0.23:5000
[Aug 26 22:22:37] NOTICE[14062]: src/mpf_bridge.c:91 Media Path ASR-26 Source->[PCMU/8000/1]->Bridge->[PCMU/8000/1]->Sink
[Aug 26 22:22:37] NOTICE[14060]: src/mrcp_client_session.c:453 Raise App Response ASR-26 <71f17a26257411ed> [2] SUCCESS [0]
[Aug 26 22:22:37] NOTICE[14060]: app_mrcprecog.c:282 speech_on_channel_add: (ASR-26) Channel ready codec=PCMU, sample rate=8000
[Aug 26 22:22:37] NOTICE[27829][C-00000012]: app_mrcprecog.c:1365 app_recog_exec: (ASR-26) Recognizing, enable DTMFs: 1, start input timers: 1
[Aug 26 22:22:37] NOTICE[14060]: src/mrcp_client_session.c:390 Receive App MRCP Request ASR-26 <71f17a26257411ed>
[Aug 26 22:22:37] NOTICE[14060]: src/mrcp_client_session.c:620 Send MRCP Request ASR-26 <71f17a26257411ed@speechrecog> [1]
[Aug 26 22:22:37] NOTICE[14061]: src/mrcp_client_connection.c:551 Send MRCPv2 Data 10.2.0.27:39342 <-> 10.2.0.23:11544 [404 bytes]
MRCP/2.0 404 RECOGNIZE 1
Channel-Identifier: 71f17a26257411ed@speechrecog
Content-Type: text/uri-list
Cancel-If-Queue: false
Start-Input-Timers: true
Confidence-Threshold: 0.7
Speech-Language: ru-RU
Speech-Incomplete-Timeout: 1000
No-Input-Timeout: 5000
Sensitivity-Level: 0.7
Speech-Complete-Timeout: 800
Recognition-Timeout: 10000
Content-Length: 37
builtin:grammar/common?language=ru-RU
[Aug 26 22:22:37] NOTICE[14061]: src/mrcp_client_connection.c:656 Receive MRCPv2 Data 10.2.0.27:39342 <-> 10.2.0.23:11544 [83 bytes]
MRCP/2.0 83 1 200 IN-PROGRESS
Channel-Identifier: 71f17a26257411ed@speechrecog
[Aug 26 22:22:37] NOTICE[14060]: src/mrcp_client_session.c:498 Raise App MRCP Response ASR-26 <71f17a26257411ed>
[Aug 26 22:22:39] NOTICE[14061]: src/mrcp_client_connection.c:656 Receive MRCPv2 Data 10.2.0.27:39342 <-> 10.2.0.23:11544 [94 bytes]
MRCP/2.0 94 START-OF-INPUT 1 IN-PROGRESS
Channel-Identifier: 71f17a26257411ed@speechrecog
[Aug 26 22:22:39] NOTICE[14060]: src/mrcp_client_session.c:514 Raise App MRCP Event ASR-26 <71f17a26257411ed>
[Aug 26 22:22:43] NOTICE[14063]: src/mrcp_sofiasip_client_agent.c:617 Receive SIP Event [nua_i_bye] Status 200 Session Terminated [asr]
[Aug 26 22:22:43] NOTICE[14063]: src/mrcp_sofiasip_client_agent.c:617 Receive SIP Event [nua_i_state] Status 200 Session Terminated [asr]
[Aug 26 22:22:43] NOTICE[14063]: src/mrcp_sofiasip_client_agent.c:555 SIP Call State ASR-26 [terminated]
[Aug 26 22:22:43] NOTICE[14060]: src/mrcp_client_session.c:479 Raise App Event ASR-26 <71f17a26257411ed> [0]
[Aug 26 22:22:43] NOTICE[14061]: src/mrcp_client_connection.c:644 TCP/MRCPv2 Peer Disconnected 10.2.0.27:39342 <-> 10.2.0.23:11544
[Aug 26 22:22:43] NOTICE[14060]: src/mrcp_client_session.c:479 Raise App Event ASR-26 <71f17a26257411ed> [0]
[Aug 26 22:28:49] WARNING[27829][C-00000012]: audio_queue.c:327 audio_queue_write: (ASR-26) Audio queue overflow!
[Aug 26 22:28:49] ERROR[27829][C-00000012]: app_mrcprecog.c:426 recog_channel_get_results: (ASR-26) Recognition terminated prematurely
[Aug 26 22:28:49] WARNING[27829][C-00000012]: app_mrcprecog.c:1524 app_recog_exec: (ASR-26) Unable to retrieve result
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client_session.c:385 Receive App Request ASR-26 <71f17a26257411ed> [1]
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client_session.c:828 Terminate Session ASR-26 <71f17a26257411ed>
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client_session.c:207 Session Terminated ASR-26 <71f17a26257411ed>
[Aug 26 22:28:49] NOTICE[14061]: src/mrcp_client_connection.c:480 Remove Control Channel <71f17a26257411ed@speechrecog> [0]
[Aug 26 22:28:49] NOTICE[14062]: src/mpf_rtp_stream.c:935 Close RTP Transmitter 10.2.0.27:28032 -> 10.2.0.23:5000 [s:18324 o:2931840]
[Aug 26 22:28:49] NOTICE[14062]: src/mpf_rtp_stream.c:418 Remove RTP Session 10.2.0.27:28032
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client_connection.c:243 Destroy TCP/MRCPv2 Connection 10.2.0.27:39342 <-> 10.2.0.23:11544
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client.c:707 Remove MRCP Handle ASR-26 <71f17a26257411ed>
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_client_session.c:453 Raise App Response ASR-26 <71f17a26257411ed> [1] FAILURE [2]
[Aug 26 22:28:49] NOTICE[14060]: src/mrcp_application.c:211 Destroy MRCP Handle ASR-26
[Aug 26 22:28:49] NOTICE[27829][C-00000012]: app_mrcprecog.c:1041 mrcprecog_exit: MRCPRecog() exiting status: ERROR on SIP/1000-00000011
@dmitriyrubbert It sounds like the Audio queue overflow in your case is not your main issue, but rather that your mrcp server is crashing.
The primary action of course is ideally to resolve whatever is causing your mrcp server to crash.
Separate from that, you could open a feature request to ask that there be some sort of idle timeout, such that asterisk-unimrcp might automatically close/cancel a recognition session if no streaming input from a server has been received over some period of time.
lazarevdmitriy
commented
1 year ago @dmitriyrubbert It sounds like the
Audio queue overflowin your case is not your main issue, but rather that your mrcp server is crashing.The primary action of course is ideally to resolve whatever is causing your mrcp server to crash.
Separate from that, you could open a feature request to ask that there be some sort of idle timeout, such that asterisk-unimrcp might automatically close/cancel a recognition session if no streaming input from a server has been received over some period of time.
Thank you. We are working on fixing the cause of our MRCP server crash. I was interested in the ability to set an idle timeout for asterisk-unimrcp. And I realized that it is not yet.
achaloyan
commented
1 year ago @dmitriyrubbert, I think you may need to set request-timeout and/or speech-channel-timeout. Both makes sense, the latter seems more appropriate to your case.
https://github.com/unispeech/asterisk-unimrcp/blob/master/conf/mrcp.conf#L34
Im getting this warning time to time, what is the reason of a queue overflow?
WARNING[57182][C-00004386] audio_queue.c: (ASR-15473) Audio queue overflow!