GNOME Bugzilla – Bug 767826
opusdec with plc enabled failing to decode audio
Last modified: 2016-06-21 09:50:22 UTC
Sending opus audio over RTP, with PLC and FEC enabled, the opusdec gets into a state where it no longer decodes any buffers. The issue only occurs when there is packet loss, and disabling plc or fed in opusdec allows it to continue decoding audio, but it's obviously less than ideal due to the cutouts in audio. I'm able to reliably recreate the issue with the following launch pipelines: server side (based on gst-plugins-good/tests/examples/rtp/server-alsasrc-PCMA.sh, just switched to opusenc): DEST=127.0.0.1 AELEM=audiotestsrc ASOURCE="$AELEM ! audioconvert" AENC="opusenc inband-fec=true ! rtpopuspay" gst-launch-1.0 -v -m rtpbin name=rtpbin \ $ASOURCE ! $AENC ! rtpbin.send_rtp_sink_0 \ rtpbin.send_rtp_src_0 ! udpsink port=5002 host=$DEST \ rtpbin.send_rtcp_src_0 ! udpsink port=5003 host=$DEST sync=false async=false \ udpsrc port=5007 ! rtpbin.recv_rtcp_sink_0 And the client side. It's based on gst-plugins-good/tests/examples/rtp/client-PCMA.sh, but changed to use opusdec and have an identity inserted for dropping packets: AUDIO_CAPS="application/x-rtp,media=(string)audio,clock-rate=(int)48000,encoding-name=(string)OPUS" AUDIO_DEC="rtpopusdepay ! opusdec plc=true use-inband-fec=true" AUDIO_SINK="audioconvert ! audioresample ! autoaudiosink" DEST=127.0.0.1 gst-launch-1.0 -v -m rtpbin name=rtpbin \ udpsrc caps=$AUDIO_CAPS port=5002 \ ! identity drop-probability=0.10 \ ! rtpbin.recv_rtp_sink_0 \ rtpbin.! $AUDIO_DEC ! $AUDIO_SINK \ udpsrc port=5003 ! rtpbin.recv_rtcp_sink_0 \ rtpbin.send_rtcp_src_0 \ ! udpsink port=5007 host=$DEST sync=false async=false Note it happens with any non-zero drop-probability, it just usually takes longer with a lower % Running the client with GST_DEBUG="opusdec:7" I'm able to catch the point were the audio stops playing - as best as I can tell it's right at the point of "missing buffer, doing PLC duration". Looks like the 99:99:99 buffer duration doesn't matter until it hits the missing buffer. Afterwards it seems confused and keeps printing "current duration 5124095:34:33.709551614 of missing data not enough for PLC (minimum needed: 0:00:00.002500000) - skipping" << more of the same before this>> 0:00:03.710085157 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:565:opus_dec_chain_parse_data:<opusdec0> decoded 960 samples 0:00:03.710157312 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.403897735, duration 99:99:99.999999999 0:00:03.710175711 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 160 0:00:03.710197538 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 0:00:03.710213085 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:539:opus_dec_chain_parse_data:<opusdec0> FEC enabled, decoding last delayed buffer 0:00:03.710333994 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:565:opus_dec_chain_parse_data:<opusdec0> decoded 960 samples 0:00:03.710402215 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.423897512, duration 99:99:99.999999999 0:00:03.710425387 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 160 0:00:03.710439248 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 0:00:03.710452574 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:539:opus_dec_chain_parse_data:<opusdec0> FEC enabled, decoding last delayed buffer 0:00:03.710633914 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:565:opus_dec_chain_parse_data:<opusdec0> decoded 960 samples 0:00:03.710727746 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.443877173, duration 99:99:99.999999999 0:00:03.710750500 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 0 0:00:03.710761205 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 0:00:03.710773195 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:539:opus_dec_chain_parse_data:<opusdec0> FEC enabled, decoding last delayed buffer 0:00:03.710912318 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:565:opus_dec_chain_parse_data:<opusdec0> decoded 960 samples 0:00:03.781393181 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.463897290, duration 99:99:99.999999999 0:00:03.781426767 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 160 0:00:03.781435646 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 << audio cuts out here ... I think >> 0:00:03.781442601 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:484:opus_dec_chain_parse_data:<opusdec0> missing buffer, doing PLC duration 99:99:99.999999999 plus leftover 0:00:00.000000000 0:00:03.781474727 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:504:opus_dec_chain_parse_data:<opusdec0> current duration 99:99:99.999999999 of missing data not enough for PLC (minimum needed: 0:00:00.002500000) - skipping 0:00:03.781501051 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.483897070, duration 99:99:99.999999999 0:00:03.781513571 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 160 0:00:03.781520889 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 0:00:03.781527173 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:484:opus_dec_chain_parse_data:<opusdec0> missing buffer, doing PLC duration 99:99:99.999999999 plus leftover 99:99:99.999999999 0:00:03.781536975 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:504:opus_dec_chain_parse_data:<opusdec0> current duration 5124095:34:33.709551614 of missing data not enough for PLC (minimum needed: 0:00:00.002500000) - skipping 0:00:03.781557109 5002 0x7f26f4003050 LOG opusdec gstopusdec.c:765:gst_opus_dec_handle_frame:<opusdec0> Got buffer ts 0:00:03.503896852, duration 99:99:99.999999999 0:00:03.781568468 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:442:opus_dec_chain_parse_data:<opusdec0> Received buffer of size 160 0:00:03.781575346 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:468:opus_dec_chain_parse_data:<opusdec0> Using buffer of size 160 0:00:03.781581728 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:484:opus_dec_chain_parse_data:<opusdec0> missing buffer, doing PLC duration 99:99:99.999999999 plus leftover 5124095:34:33.709551614 0:00:03.781591523 5002 0x7f26f4003050 DEBUG opusdec gstopusdec.c:504:opus_dec_chain_parse_data:<opusdec0> current duration 5124095:34:33.709551613 of missing data not enough for PLC (minimum needed: 0:00:00.002500000) - skipping << more of the same after this>>
Created attachment 330008 [details] full debug log from client More readable version of the client's GST_DEBUG output.
Sorry, forgot to mention I'm running 1.8.2 on linux. $ gst-launch-1.0 --version gst-launch-1.0 version 1.8.2 GStreamer 1.8.2 Unknown package origin
I should also note that if I run opusenc ! identity ! opusdec in a single pipeline, with no RTP, the buffer duration is the expected 20ms (rather than 99:99:99.99999) and the issue does not occur.
I can see it, and assuming a duration of 20ms when the duration is unknown works. However, since all the durations are unknown, even for non missing buffers, we can't be sure of the missing duration. I could track the timestamp differences between non-missing buffers, and use that as a default duration for the missing ones, but durations can change at will within a stream I think, so that's not foolproof.
At first, I tired patching opus_dec_chain_parse_data() so that when calculating samples, in addition to checking for a non-0 sized bufd, it also checked for a valid duration. This seemed to work better, but it would still occasionally fail at runtime (opus_multistream_decode() returned BUFFER_TOO_SMALL). I'm currently running with opus_dec_chain_parse_data() hard-coded to the max number of samples. So far this has been working for me. Let me know if there's anything I can to do help test/debug.
Created attachment 330061 [details] [review] handle buffers with no duration This works with the example pipelines, though is a bit of guesswork.
That'd work (I tried that too), but sounds worse. Maybe we could rework that FEC/PLC code to decode max, but deduce missing amount from what';s returned. It'd only work for FEC though, since for PLC we'd get as much as we asked. So not great either, and needs rejiggling that code, which was rather easy to break IIRC.
> since all the durations are unknown, even for non missing buffers, > we can't be sure of the missing duration Being new to much of this (gstreamer, opus, and RTP) I was curious if this is expected? In the local-loopback test the durations appeared to be valid in the buffers sent to the decoder. I would have expected payloading and depayloading through RTP to preserve the duration too.
I'd have expected it too, but I don't know much about RTP. I guess it could be a bug in the opus payloader. I'll have a look to see if there's anything obviously wrong.
Other depayloaders seem to set duration not based on any received duration, and most do not set it. I'll see if I can get that info from parsing the opus packets.
Review of attachment 330061 [details] [review]: ::: ext/opus/gstopusdec.c @@ +484,3 @@ + if (!GST_CLOCK_TIME_IS_VALID (missing_duration)) { + if (GST_CLOCK_TIME_IS_VALID (dec->last_known_buffer_duration)) { + missing_duration = dec->last_known_buffer_duration; Can't we get the duration from the Opus packet?
I thought I could, but AFACIT there's only an API to call from an opus decoder, as opposed to a multistream opus decoder, so I'm not sure how to do that.
You wrote some code for that in gst-plugins-base/ext/ogg/gstoggstream.c for getting the number of samples from an Opus packet ;)
Oh man, that guy's clever, I'll nick that code :D Thanks
Created attachment 330119 [details] [review] handle buffers with no duration Works :) Still not foolproof since for all we know, the missing buffer had a differnet length from the previous one, but that's the best we can do here, at least from the decoder's pov.
Comment on attachment 330119 [details] [review] handle buffers with no duration Seems reasonable
Thanks. commit 6bc6b6ebbfb35796e3dfd22f15ebabb685bd4576 Author: Vincent Penquerc'h <vincent.penquerch@collabora.co.uk> Date: Mon Jun 20 12:42:28 2016 +0100 opusdec: handle missing buffers with no duration If buffer duration is missing, it is parsed from the packet data. This is not foolproof, since Opus can change durations on the fly. https://bugzilla.gnome.org/show_bug.cgi?id=767826