Pulseeffects: Audio cuts out sometimes when enabling/disabling plugins

[Lchu613]

Having an interesting issue where enabling/disabling plugins will sometimes cause audio to stop playing. I've gotten this to happen by switching profiles or by repeated toggling any of Bass Enhancer, Loudness, Equalizer on and off until it happens. Observing with G_MESSAGES_DEBUG=pulseeffects pulseeffects, I can see that some of the time, nothing unusual is outputted when audio cuts out; in addition, pavucontrol's outputs still shows PulseEffects(apps) as playing audio, but nothing is coming from Built-in Audio Analog Stereo.
In these cases where no error occurs, I can sometimes wait for "sie: PLAYING -> PAUSED -> READY", at which point if I start playing audio again everything works fine. However, on a few occasions I see some errors similar to the following, always starting with the "Internal data stream error":

G_MESSAGES_DEBUG=pulseeffects pulseeffects
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.516: application: PE version: 4.4.0
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.518: pulse_manager: context is connecting
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.518: pulse_manager: context is authorizing
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: context is setting name
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: context is ready
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: connected to: unix:/run/user/1000/pulse/native
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: protocol version: 32
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: Pulseaudio version: 12.2
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: default pulseaudio source: alsa_input.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: default pulseaudio sink: alsa_output.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.519: pulse_manager: loading Pulseeffects applications output sink...
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.520: pulse_manager: default pulseaudio sink sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.520: pulse_manager: default pulseaudio sink audio format: s16le
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.520: pulse_manager: sink loaded
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.520: pulse_manager: loading Pulseeffects microphone output sink...
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.521: pulse_manager: default pulseaudio source sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.521: pulse_manager: default pulseaudio source audio format: s16le
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.522: pulse_manager: sink loaded
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.539: sie: using input device: PulseEffects_apps.monitor
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.539: sie: using output device: alsa_output.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.563: sie: limiter enabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.573: sie: equalizer enabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.579: sie: bass_enhancer enabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.614: sie: autogain enabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.625: soe: using output device: PulseEffects_mic
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.625: soe: using input device: alsa_input.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.645: presets_manager: user preset directory already exists: /home/lschu/.config/PulseEffects
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:44.994: convolver_ui: irs directory already exists: /home/lschu/.config/PulseEffects/irs
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.397: sie: spectrum enabled
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.398: soe: spectrum enabled
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: sie: using output device: alsa_output.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: application_ui: output device changed: alsa_output.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: application_ui: added sink: alsa_output.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: application_ui: added source: alsa_output.pci-0000_00_1f.3.analog-stereo.monitor
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: soe: using input device: alsa_input.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: application_ui: input device changed: alsa_input.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:45.734: application_ui: added source: alsa_input.pci-0000_00_1f.3.analog-stereo
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.734: sie: NULL -> READY -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.735: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.755: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.755: sie: pulsesrc buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.755: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.815: peadapter: pulseaudio block size 480 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.816: peadapter: we will read in chunks of 512 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.820: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.820: sie: pulsesink buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.820: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:48.823: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:57.985: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:58.377: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:58.798: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:59.188: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:59.521: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:35:59.894: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:00.228: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:00.617: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:00.977: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:01.824: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:07.805: sie: autogain disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:08.154: sie: autogain enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:10.287: sie: limiter disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:10.574: sie: limiter enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:12.586: sie: equalizer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:12.856: sie: equalizer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:14.744: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:15.049: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:29.556: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:29.561: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.709: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.731: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.750: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.750: sie: pulsesrc buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.788: peadapter: pulseaudio block size 480 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.788: peadapter: we will read in chunks of 512 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.792: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.792: sie: pulsesink buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.792: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:39.792: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:50.902: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:36:50.905: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.219: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.249: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.255: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.255: sie: pulsesrc buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.291: peadapter: pulseaudio block size 480 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.291: peadapter: we will read in chunks of 512 frames
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.295: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.295: sie: pulsesink buffer [us]: 200000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.296: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:18.296: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:25.155: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:25.418: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:25.704: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:26.044: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:26.420: sie: bass_enhancer disabled: NULL -> VOID_PENDING

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:38:26.464: sie: Internal data stream error.
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:26.464: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason not-linked (-1)

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:38:26.465: sie: Internal data stream error.
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:26.465: sie: gstqueue.c(988): gst_queue_handle_sink_event (): /GstPipeline:pipeline/GstQueue:queue0:
streaming stopped, reason not-linked (-1)
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:26.844: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:56.186: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:56.198: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.593: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.596: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.601: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.601: sie: pulsesrc buffer [us]: 200000

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.637: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.638: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:38:57.638: gst_segment_to_stream_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.638: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.638: sie: pulsesink buffer [us]: 200000

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:38:57.638: sie: Internal data stream error.
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.638: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason error (-5)
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.673: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:38:57.673: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:09.541: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:09.545: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.522: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.523: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.525: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.525: sie: pulsesrc buffer [us]: 200000

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:39:46.533: gst_segment_to_stream_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.534: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.534: sie: pulsesink buffer [us]: 200000

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:39:46.534: sie: Internal data stream error.
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.534: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason error (-5)
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.535: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:46.535: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:57.665: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:39:57.674: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.678: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.684: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.686: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.686: sie: pulsesrc buffer [us]: 200000

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.729: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.729: gst_segment_to_stream_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.729: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.730: sie: pulsesink buffer [us]: 200000

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:40:12.730: sie: Internal data stream error.

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_running_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.730: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason error (-5)

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:12.730: gst_segment_to_stream_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.732: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:12.732: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:25.962: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:25.967: sie: PAUSED -> READY -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.495: sie: sampling rate: 48000 Hz
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.505: sie: READY -> PAUSED -> PLAYING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.505: sie: pulsesrc latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.505: sie: pulsesrc buffer [us]: 200000

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_running_time: assertion 'segment->format == format' failed

(pulseeffects:20138): GStreamer-CRITICAL **: 22:40:31.515: gst_segment_to_stream_time: assertion 'segment->format == format' failed
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.520: sie: pulsesink latency [us]: 10000
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.520: sie: pulsesink buffer [us]: 200000

(pulseeffects:20138): pulseeffects-CRITICAL **: 22:40:31.520: sie: Internal data stream error.
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.520: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason error (-5)
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.531: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:31.532: sie: total latency: 120 ms
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:42.929: sie: PLAYING -> PAUSED -> READY
(pulseeffects:20138): pulseeffects-DEBUG: 22:40:42.932: sie: PAUSED -> READY -> VOID_PENDING

After this error happens, audio through PulseEffects will just not work until I restart PulseEffects.

[wwmm]

Sometimes this happens here too. Once you have a not-linked error only restarting PulseEffects pipeline (pausing/unpausing an app) you can have sound again. I still don't know what is causing this problem. Probably there is something I am not doing right when dynamically inserting/removing elements to/from the GStreamer pipeline

[wwmm]

One of the things that makes this bug so hard to find is that it is not easy to reproduce. For example enabling/disabling the bass enhancer here does nothing. I have to alternate presets that enable/disable many plugins at once. And even this way it is not always I can make it happen. It feels like there is a timing issue somewhere

[betterphp]

Not sure if it's related but I've had this after disconnecting and reconnecting my Bluetooth headphones a few times. Restarting pulseeffects always seems to bring it all back to normal.

[shameerariff]

I do have the same problem, It happens especially when changing the EQ mode or restarting the pulseeffects.

[wwmm]

By EQ mode you mean changing the number of bands? I tried my best to make the change of bands number bug free but it feels like GStreamer equalizer does not like the idea of changing this parameter on the fly... =/

[wwmm]

Anyway the issue described by the opener is probably being caused by a hard to find problem in the way I am implementing the GStreamer dynamic pipeline. This is the way to add or remove effects on the fly. They are really hard to get right. So the probability I am doing something wrong is high. But at this moment I have no idea of what could be.

A second possibility is that the dynamic pipeline is right but there is some kind of multithreading bug when changing it....

And a third possibility is that one the buffer size adapter plugin I had to right has anon obvious problem that breaks the dynamic pipeline. For now there are too many variables =/

[wwmm]

I am doing a few changes for version 4.4.1 that seem to help with this. But I can see that eventually the crash still happens. Totally at random =/

[wwmm]

At least for me these crashes never happen when I switch profiles when no app is playing audio. It is something that is only triggered when the pipeline is running

[shameerariff]

In the same time I noticed especially while loading the pages on firefox or chromium also affect the pulseeffects. In detail I used to play audio using VLC or RhythmBox, and it was routed via pulseeffects, while I am browsing some websites especially while loading or reloading a webpage the audio was muted but the player continues plays after a while automatically it resumes. I looks strange. The operating system I have is the Ubuntu the latest version which was deployed on macbook hardware.

[vmatare]

To me this looks a lot like a race condition, so I'd guess that you're not locking something that should be locked.

[vmatare]

And very strangely, with Gentoo's 4.4.0 ebuild, playback works fine most of the time, but with the 4.4.0 release from github, as well as with the current master, I can't get any playback at all.
Edit: The only difference between the two is actually the build options. The source is the same. All of this points very clearly to a race condition.

[wwmm]

@vmatare what is printed in the terminal when running in debug mode G_MESSAGES_DEBUG=pulseeffects pulseeffects and there is no playback at all?

It feels like a race condition and I have been playing with locking in the last months with no luck. I have been trying to take a look at GStreamer logs but it doesn't say the source of the crashes in the pipeline

[shameerariff]

This was the response (pulseeffects:3820): pulseeffects-DEBUG: 20:07:49.514: application: destroyed on running the command G_MESSAGES_DEBUG=pulseeffects pulseeffects. If I am wrong somewhere kindly correct me.

[wwmm]

This is too short. You probably had an instance of PulseEffects already running. Try to kill it first using pulseeffects -q

[shameerariff]

Kindly check this out
I started pulseeffects on command mode and this was the feedback
`(pulseeffects:4068): pulseeffects-CRITICAL **: 20:27:02.070: sie: Internal data stream error.

(pulseeffects:4068): pulseeffects-CRITICAL **: 20:27:02.071: sie: Internal data stream error.

`

[shameerariff]

Probably this too will help you out

log

(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.223: application: PE version: 4.4.0
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.274: pulse_manager: context is connecting
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.290: pulse_manager: context is authorizing
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: context is setting name
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: context is ready
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: connected to: unix:/run/user/1000/pulse/native
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: protocol version: 32
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: Pulseaudio version: 12.2
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: default pulseaudio source: alsa_input.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.291: pulse_manager: default pulseaudio sink: alsa_output.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.292: pulse_manager: loading Pulseeffects applications output sink...
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.292: pulse_manager: default pulseaudio sink sampling rate: 44100 Hz
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.292: pulse_manager: default pulseaudio sink audio format: s16le
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.306: pulse_manager: sink loaded
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.307: pulse_manager: loading Pulseeffects microphone output sink...
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.307: pulse_manager: default pulseaudio source sampling rate: 44100 Hz
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.307: pulse_manager: default pulseaudio source audio format: s16le
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.307: pulse_manager: sink loaded
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.477: sie: using input device: PulseEffects_apps.monitor
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.477: sie: using output device: alsa_output.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.596: sie: compressor enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.650: sie: equalizer enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.685: sie: reverb enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.718: sie: bass_enhancer enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.884: sie: multiband_compressor enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:24.896: sie: loudness enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:25.216: sie: autogain enabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:25.247: soe: using output device: PulseEffects_mic
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:25.247: soe: using input device: alsa_input.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:25.413: presets_manager: user preset directory already exists: /home/shameerariff/.config/PulseEffects
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:26.354: convolver_ui: irs directory already exists: /home/shameerariff/.config/PulseEffects/irs
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.112: sie: spectrum enabled
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.113: soe: spectrum enabled
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.767: sie: using output device: alsa_output.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.767: application_ui: output device changed: alsa_output.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.767: application_ui: added sink: alsa_output.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.768: application_ui: added sink: alsa_output.pci-0000_00_08.0.analog-stereo.equalizer
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.769: application_ui: added source: alsa_output.pci-0000_00_08.0.analog-stereo.monitor
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.769: soe: using input device: alsa_input.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.769: application_ui: input device changed: alsa_input.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.769: application_ui: added source: alsa_input.pci-0000_00_08.0.analog-stereo
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.770: application_ui: added source: alsa_output.pci-0000_00_08.0.analog-stereo.equalizer.monitor
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:27.818: sie: sampling rate: 44100 Hz
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.029: sie: NULL -> READY -> PLAYING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.066: sie: READY -> PAUSED -> PLAYING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.119: sie: pulsesrc latency [us]: 10000
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.124: sie: pulsesrc buffer [us]: 200000
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.205: peadapter: pulseaudio block size 441 frames
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.205: peadapter: we will read in chunks of 512 frames
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.291: sie: pulsesink latency [us]: 10000
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.291: sie: pulsesink buffer [us]: 200000
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.377: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:28.377: sie: total latency: 121 ms
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:37.918: sie: bass_enhancer disabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:38.402: sie: bass_enhancer enabled: PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:43.130: sie: loudness disabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:43.574: sie: loudness enabled: PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:44.439: sie: loudness disabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:45.061: sie: loudness enabled: PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:49.370: sie: equalizer disabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:50.293: sie: equalizer enabled: PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:50.748: sie: equalizer disabled: NULL -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:51.422: sie: equalizer enabled: PLAYING -> VOID_PENDING
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:54.873: sie: reverb disabled: NULL -> VOID_PENDING

(pulseeffects:10985): pulseeffects-CRITICAL **: 20:28:54.904: sie: Internal data stream error.
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:54.904: sie: gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason not-linked (-1)

(pulseeffects:10985): pulseeffects-CRITICAL **: 20:28:54.905: sie: Internal data stream error.
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:54.905: sie: gstqueue.c(988): gst_queue_handle_sink_event (): /GstPipeline:pipeline/GstQueue:queue0:
streaming stopped, reason not-linked (-1)
(pulseeffects:10985): pulseeffects-DEBUG: 20:28:55.259: sie: reverb enabled: PLAYING -> VOID_PENDING

[vmatare]

It's pretty much what has been reported before. It's just these repeating every second or so:

(pulseeffects:7269): pulseeffects-CRITICAL **: 20:31:12.888: sie: Internal data stream error.
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:12.888: sie: /var/tmp/portage/media-libs/gstreamer-1.14.4/work/gstreamer-1.14.4/libs/gst/base/gstbasesrc.c(3055): gst_base_src_loop (): /GstPipeline:pipeline/GstPulseSrc:source:
streaming stopped, reason not-linked (-1)
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:12.889: sie: NULL -> VOID_PENDING
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.739: sie: NULL -> READY -> PLAYING
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.739: sie: READY -> PAUSED -> PLAYING
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.739: sie: PAUSED -> PLAYING -> VOID_PENDING
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.739: sie: total latency: 0 ms
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.744: sie: pulsesrc latency [us]: 100000
(pulseeffects:7269): pulseeffects-DEBUG: 20:31:16.744: sie: pulsesrc buffer [us]: 800000

All the while spotify keeps on playing happily, while pulseeffects displays & outputs only silence.

[vmatare]

So I'd like to give this a shot, but can you give me some pointers where I should start looking within your codebase? E.g. where have you been experimenting with the locking? Also I'm not entirely clear on what exact role gstreamer plays in the whole pipeline. Give me just a few hints and I'll try to figure it out ;-)

[wwmm]

Once you have a not-linked error the pipeline is dead and no audio will be played.

When we think about the audio processing there are two big groups in PulseEffects. One that interacts with Pulseaudio and another one that applies the effects. This last one is entirely on GStreamer. Once the pulsesrc plugins gets the audio sample from Pulseaudio we apply a series of plugins and the processed audio is played in Gstreamer's pulsesink plugin. You can see more about this process in the file pipeline_base.cpp

I will explain the general idea of what is being done and point you to the right files in the code base. But the first thing to do is reading a little about dynamic GStreamer pipelines because that is what we have in PulseEffects. Take a look at the section Changing elements in a pipeline in this site pipeline manipulation. This one is old but is also helpful gstreamer-dynamic-pipelines

Now to the code. these are the files where the pipeline is manipulated plugin_base.cpp, sink_input_effects.cpp. There is another file but it is relevant only for effects applied to microphone. Its structure is equal to the one in sink_input_effects.cpp. So there is no need to focus on it now.

There are two things that can be done in our Pipeline. Removing/Adding a plugin from/to the processing chain(this is what the effect enable switch does) or changing the effects order. The first case is handled in plugin_base.cpp and the effects order in sink_input_effects.cpp. When we alternate between presets both things can happen and that is the source of the issue. When I created a preset that did not reorder the plugins there was no problem. When I created a preset that that only reordered without touching the enable/disabled state there was also no problem. Issues happen when we try to do both.

So the solution seems simple. Do not do them at the same time! The problem is that it took a long time to have dynamic pipelines in PulseEffects (and to be honest it is not like I fully understand them) and the rest of the code did not evolve in a way that makes this solution simple to implement( at least to me :-) ). I will explain what happens when the user chooses a preset. Once the file is loaded what I do is updating the corresponding GSettings keys. The interface widgets, plugins parameters and whatever more needs to be updated is connected to GSsettings through gobject bindings. This made my life really easy at the time because GSettings takes care of propagating all the changes. The problem is that I have no control over the time when GSettings decides to update each key. It is an asynchronous process. And I imagine this is the reason why the effects reordering is colliding with the enable/disable plugins code. Depending on when GSettings gives the instructions to every one bound to the keys about their updated values something odd happens in the Pipeline.

There are probably a few things that will seem odd in the code design... But as I am a computational physicist with no formal education in software engineering I took the freedom to do what was easiest from the point of view of a lonely developer XD In any case fell free to ask more questions and to make general suggestions that you think are appropriated.

[wwmm]

Although it seems that serializing the updates to the effects reordering and to the enabled state will solve the problem I still do not see why the pipeline is having problems with the async approach. I am reading what I can about GStreamer dynamic pipelines and it is not clear at all why this is an issue if the pad probes are being serialized through a mutex =/

[wwmm]

I did a few changes that improved a lot the situation. It seems that using GST_PAD_PROBE_TYPE_BLOCK_DOWNSTREAM and eos (end of stream) events is not as simple as I thought =/ Now that I am using GST_PAD_PROBE_TYPE_IDLE and removed one of the eos events the only crash that eventually happens is a Floating point exception somewhere inside GStreamer. But this one is way harder to reproduce.

[shameerariff]

I did a few changes that improved a lot the situation. It seems that using GST_PAD_PROBE_TYPE_BLOCK_DOWNSTREAM and eos (end of stream) events is not as simple as I thought =/ Now that I am using GST_PAD_PROBE_TYPE_IDLE and removed one of the eos events the only crash that eventually happens is a Floating point exception somewhere inside GStreamer. But this one is way harder to reproduce.

It's doing good now.
Thank you for your kind support.

[wwmm]

I released PulseEffects 4.4.1 with these changes.

[Lchu613]

Aha, missed your update but independently discovered a few days ago that reordering the effects in the presets so they all had the same ordering almost entirely eliminated the problem in 4.4.0. Your explanation for why that phenomenon happens is very interesting. Will see how things go on 4.4.1.

[wwmm]

As I can not reproduce this anymore I will close this issue. The pipeline crash related to a Floating point exception somewhere inside GStreamer still happens occasionally at random when switching profiles... But as it seems to have a totally different source it is better to track this one in another issue.