detect silence and avoid sending empty packets

[totaam]

Issue migrated from trac ticket # 1617

component: sound | priority: major | resolution: fixed

2017-08-08 12:51:55: antoine created the issue

---

gstreamer's cutter element: Analyses the audio signal for periods of silence. The start and end of silence is signalled by bus messages named cutter - we could use this to tell the receiver to pause and resume.

Not sure if we want to / should wait for the pipeline to drain first.

See also: #1212.

[totaam]

2017-08-10 12:29:10: antoine changed status from new to assigned

[totaam]

2017-08-10 12:29:10: antoine commented

---

Testing using gst-launch-1.0, I found that the opus codec just refuses to work with cutter in the pipeline

gst-launch-1.0 -m \
    pulsesrc ! queue ! cutter \
    opusenc !
    fakesink

All the other codecs+muxers work.
(adding audioconvert after cutter as needed, see ENCODER_NEEDS_AUDIOCONVERT=("flacenc", "wavpackenc"))

Here's the error:

$ gst-launch-1.0 -m  pulsesrc ! queue ! cutter ! audioconvert ! opusenc !  fakesink
(...)
New clock: GstPulseSrcClock
Got message #41 from object "audiosrcringbuffer0" (stream-status): GstMessageStreamStatus, type=(GstStreamStatusType)GST_STREAM_STATUS_TYPE_ENTER, owner=(GstElement)"\(GstPulseSrc\)\ pulsesrc0", object=(GThread)NULL;
Got message #43 from element "opusenc0" (state-changed): GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;
Got message #44 from element "pulsesrc0" (latency): no message details
Redistribute latency...
Got message #45 from element "audioconvert0" (state-changed): GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;
Got message #46 from element "cutter0" (state-changed): GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;
Got message #48 from element "queue0" (state-changed): GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;
Got message #49 from element "pulsesrc0" (state-changed): GstMessageStateChanged, old-state=(GstState)GST_STATE_PAUSED, new-state=(GstState)GST_STATE_PLAYING, pending-state=(GstState)GST_STATE_VOID_PENDING;
Got message #55 from element "pulsesrc0" (error): GstMessageError, gerror=(GError)NULL, debug=(string)"gstbasesrc.c\(2939\):\ gst_base_src_loop\ \(\):\ /GstPipeline:pipeline0/GstPulseSrc:pulsesrc0:\012streaming\ stopped\,\ reason\ not-negotiated\ \(-4\)", details=(structure)"details\,\ flow-return\=\(int\)-4\;";
ERROR: from element /GstPipeline:pipeline0/GstPulseSrc:pulsesrc0: Internal data stream error.
Additional debug info:
gstbasesrc.c(2939): gst_base_src_loop (): /GstPipeline:pipeline0/GstPulseSrc:pulsesrc0:
streaming stopped, reason not-negotiated (-4)
(..)

[totaam]

2017-08-10 13:52:01: antoine changed status from assigned to new

[totaam]

2017-08-10 13:52:01: antoine changed owner from antoine to maxmylyn

[totaam]

2017-08-10 13:52:01: antoine commented

---

This seems to work well enough (with some caveats below), so added in r16675 (see commit for details).

Since this doesn't work with opus (for whatever reason - and maybe other codecs too..), maybe we should switch to another codec as default? (and file an upstream ticket to figure out why / how to fix this)

There was just one annoying limitation: the cutter element doesn't fire initially if the sound level starts already below the threshold. So as of r16676 we now play a short bell sample whenever a client starts forwarding sound. This ensures that the sound level goes above the threshold at least once.

We could also have added a level element in the pipeline and duplicate the "cutter" code to figure out what the initial state should be... but this wouldn't be 100% reliable.

---

With "-d gstreamer", when the stream goes near silent we see:

sound source on_message: <Gst.Message object at 0x7f1342639258 (GstMessage at 0x556c2f2d0200)>
sound source cutter message, above=False, min-timestamp=0, max-timestamp=63440000000
sound source cutter: skipping buffer with pts=63450000000 (max-timestamp=63440000000)
(...)

Followed by constant "skipping buffer" messages.

And when the level rises again, we see:

(skipping buffer repeated)
sound source on_message: <Gst.Message object at 0x7f1342639258 (GstMessage at 0x556c2f2d0100)>
sound source cutter: skipping buffer with pts=64150000000 (max-timestamp=63440000000)
sound source cutter: skipping buffer with pts=64160000000 (max-timestamp=63440000000)
sound source cutter message, above=True, min-timestamp=64340000000, max-timestamp=0
sound source cutter: skipping buffer with pts=64170000000 (min-timestamp=64340000000)
(..)
sound source cutter: skipping buffer with pts=64330000000 (min-timestamp=64340000000)

---

@maxmylyn: ready for you to test (just don't use one of the broken codecs like opus). When no sound is being played, the sound subprocess should be mostly idle and there should not be any sound network traffic, the client sound buffer level should be stable near the minimum limit.
When the volume reaches 2%, it should start forwarding again.

Note: there seems to be some problems (at least with the win32 builds) with some of the codecs, I'm not sure which ones are having problems because of this change and which ones have just bitrotted. flac, wav, wavpack and mp3 (on Linux) worked OK during testing. opus and vorbis did not..

[totaam]

2017-08-10 20:28:39: maxmylyn changed owner from maxmylyn to antoine

[totaam]

2017-08-10 20:28:39: maxmylyn commented

---

I'm seeing the same behavior as you noted (trunk r16677 Fedora 25 server and client) - flac/wav/wavpack/mp3 seem to behave nicely. Do you want me to go ahead and close this or do you want to do more work and get it working with opus and vorbis as well?

I'm assuming it's the latter.

[totaam]

2017-08-11 00:14:42: maxmylyn commented

---

I guess I should clarify a bit. I'm fine with just switching the defaults, especially now that MP3 is a free codec. I think it would be nice if we could get this for all the sound codecs(okay I'm mostly hoping for Vorbis), but it's definitely not necessary if it's a ton of work.

[totaam]

2017-09-08 11:15:18: antoine changed status from new to closed

[totaam]

2017-09-08 11:15:18: antoine set resolution to fixed

[totaam]

2017-09-08 11:15:18: antoine commented

---

I've tried everything I could think of (re-ordering the pipeline, caps, etc) but I just cannot get "vorbis" or "opus" to play nice with the "cutter" element.
So r16804 disables cutter with "vorbis" and makes "mp3" the default again. r16805 also disables it for "wavpackenc" and "avenc_aac".

I've asked the gstreamer-devel mailing list: cutter with vorbis or opus: not-negotiated error

If and when we get an answer, I'll update the code accordingly if possible. Closing for now.

[totaam]

2017-09-12 03:02:51: antoine commented

---

XPRA_CUTTER_THRESHOLD=VALUE (defaults to 0.02=2%) can be used to control the maximum level required before cutter will kick in.
Setting it to 0 will disable cutter.

[totaam]

2017-09-12 15:13:49: antoine commented

---

Related changes:

• r16831: fix some debug level gstreamer internal warnings with timestamps
• r16828: re-enable "vorbis" and "vorbis+ogg" with gstreamer versions 1.12 and later (seems to work fine - not tried older versions), also remove outdated code
• r16829: better location for volume element
• r16830: fix opus so it can use cutter! (got a reply on the gstreamer mailing list which put me on the right track)
• r16832 + r16833: make opus the default again, but blacklist all codecs that use a muxer as this still doesn't work with cutter (no idea why)

---

More information on the muxer problem:

• with vorbis and webmmux / matroskademux, the error shows up as:

gst-stream-error-quark: Could not demultiplex stream. (9)

• with vorbis and oggmux / oggdemux, the error shows up as:

Could not decode stream. gstoggdemux.c(4556)
gst_ogg_demux_handle_page () /GstPipeline pipeline0/GstOggDemux, oggdemux0, unknown ogg pad for serial 7dfefd6e detected

[totaam]

2017-09-14 16:53:46: antoine commented

---

r16845 makes it possible to debug the cutter element specifically using the env var XPRA_SOUND_LOG_CUTTER=1, so we can see when the sound level goes above or below the threshold:

sound source cutter message, above=False, min-timestamp=0, max-timestamp=840000000
sound source cutter message, above=True, min-timestamp=13090000000, max-timestamp=0
sound source cutter message, above=False, min-timestamp=0, max-timestamp=19060000000
sound source cutter message, above=True, min-timestamp=22980000000, max-timestamp=0
sound source cutter message, above=False, min-timestamp=0, max-timestamp=28660000000
sound source cutter message, above=True, min-timestamp=30810000000, max-timestamp=0

[totaam]

2017-09-15 06:10:31: antoine commented

---

More testing and information in #1638#comment:4.

wavenc was having problems with cutter, so r16847 adds it to the cutter blacklist.

[totaam]

2017-11-02 12:20:20: antoine commented

---

More fine tuning in r17285.

[totaam]

2019-06-11 12:11:10: antoine commented

---

See also #2325