Negotiation fails between depayloader and decoder

ferrieux · April 3, 2025, 11:45pm

Hi,
I’m struggling to understand why the negotiation fails on the following pipeline, which simply tries to get SBC audio from Bluetooth (avdtpsrc) and depayload and decode it. I’ve shortened it to the minimum exhibiting the issue, hence the fakesink:

gst-launch-1.0 -v avdtpsrc transport=/org/bluez/hci0/dev_38_78_62_D0_81_8A/fd2 ! rtpsbcdepay ! typefind ! sbcdec  ! fakesink

The main outcome is a failure to negotiate, when the first buffer of sound tries to get through:

ERROR: from element /GstPipeline:pipeline0/GstAvdtpSrc:avdtpsrc0: Internal data stream error.
Additional debug info:
../libs/gst/base/gstbasesrc.c(3187): gst_base_src_loop (): /GstPipeline:pipeline0/GstAvdtpSrc:avdtpsrc0:
streaming stopped, reason not-negotiated (-4)

Note the output from -v gives the following “converged” caps:

/GstPipeline:pipeline0/GstAvdtpSrc:avdtpsrc0.GstPad:src: caps = application/x-rtp, media=(string)audio, payload=(int)96, encoding-name=(string)SBC, clock-rate=(int)44100
/GstPipeline:pipeline0/GstRtpSbcDepay:rtpsbcdepay0: extensions = <  >
/GstPipeline:pipeline0/GstRtpSbcDepay:rtpsbcdepay0.GstPad:src: caps = audio/x-sbc, rate=(int)44100
/GstPipeline:pipeline0/GstTypeFindElement:typefindelement0.GstPad:src: caps = audio/x-sbc, rate=(int)44100
/GstPipeline:pipeline0/GstTypeFindElement:typefindelement0.GstPad:sink: caps = audio/x-sbc, rate=(int)44100
/GstPipeline:pipeline0/GstRtpSbcDepay:rtpsbcdepay0.GstPad:sink: caps = application/x-rtp, media=(string)audio, payload=(int)96, encoding-name=(string)SBC, clock-rate=(int)44100

The typefind shows an audio/x-sbc,rate=44100 which is expected.

The inspection of sbcdec seems to indicate it should be happy with that, but it is not:

Pad Templates:
  SINK template: 'sink'
    Availability: Always
    Capabilities:
      audio/x-sbc
               channels: [ 1, 2 ]
                   rate: { (int)16000, (int)32000, (int)44100, (int)48000 }
                 parsed: true

I noticed the extra channels and parsed properties, so I tried inserting a constraint:

 ... ! audio/x-sbc,rate=44100,channels=1,parsed=true ! ...

… to no avail

In terms of debugging techniques, I know of -v to get (only) the successful negotiations. To see the more detailed process I also know of GST_CAPS in GST_DEBUG, but it seems to WARN only on empty intersections, not on underspecified caps. Indeed I displayed the *.dot and noticed that sbcdec still had underspecified rate and channels, ignoring the constraint:

I would really appreciate if a kind soul could explain what the problem is, or suggest a better technique to analyze the failing negotiation

Thanks a lot in advance,

-Alex

Jafeth.Garcia · April 7, 2025, 4:05pm

Hi, you could get further information about what is happening by increasing the overall logging output:

GST_DEBUG=*:4 gst-launch-1.0 -v avdtpsrc transport=/org/bluez/hci0/dev_38_78_62_D0_81_8A/fd2 ! rtpsbcdepay ! typefind ! sbcdec  ! fakesink

I did an attempt at a similar pipeline without the avdtpsrc by using this pipeline:

gst-launch-1.0 audiotestsrc freq=1000 ! audio/x-raw,rate=44100,channels=2 ! \
sbcenc !  audio/x-sbc,channels=2 ! rtpsbcpay ! \
application/x-rtp,payload=96,clockrate=44100,encoding-name=SBC ! \
udpsink host=127.0.0.1 port=5004

And the following receiver pipeline:

GST_DEBUG=*:4 gst-launch-1.0 udpsrc port=5004 ! \
application/x-rtp,payload=96,clock-rate=44100 ! rtpsbcdepay ! \
sbcdec ! fakesink

And the issue up until the point was the sbcdec plugin. This was not negotiating properly in the test pipeline. I have yet to find a proper setting for it but you could check if the same is the case for you.

ferrieux · April 7, 2025, 6:03pm

Hi Jafeth,
Yes, I do replicate. Thanks for the idea BTW, separating variables is really nice !
Now, I understand the SBC codec is in plugins-bad for a reason; but what is more troublesome is the lack of efficient tools to debug such a mis-negotiation. The verbose logs are useless, as they fail to highlight the useful info. Maybe it should be possible to post-process them, based on knowledge about the critical “weak signals”. Any idea welcome.

ferrieux · April 7, 2025, 6:15pm

As an illustration, I used GST_DEBUG=GST_CAPS:4 on your receiver pipeline, and first got pretty clear warnings about missing attributes (parsed,channels):

$ GST_DEBUG=GST_CAPS:4  gst-launch-1.0 udpsrc port=5004 ! application/x-rtp,payload=96,clock-rate=44100 ! rtpsbcdepay ! sbcdec ! fakesink

0:00:00.053102215  3743 0x7f1f90000b70 WARN                GST_CAPS gstpad.c:3275:gst_pad_query_accept_caps_default:<sbcdec0:sink> caps: audio/x-sbc, rate=(int)44100 were not compatible with: audio/x-sbc, channels=(int)[ 1, 2 ], rate=(int){ 16000, 32000, 44100, 48000 }, parsed=(boolean)true
0:00:00.053130872  3743 0x7f1f90000b70 WARN                GST_CAPS gstpad.c:5888:pre_eventfunc_check:<sbcdec0:sink> caps audio/x-sbc, rate=(int)44100 not accepted

So, I inserted the constraint audio/x-sbc,parsed=true,channels=1 , which sure enough silenced the warning … but still ended up in a failed negotiation

$ GST_DEBUG=GST_CAPS:4  gst-launch-1.0 udpsrc port=5004 ! application/x-rtp,payload=96,clock-rate=44100 ! rtpsbcdepay ! audio/x-sbc,parsed=true,channels=1 ! sbcdec ! fakesink

ERROR: from element /GstPipeline:pipeline0/GstUDPSrc:udpsrc0: Internal data stream error.
Additional debug info:
../libs/gst/base/gstbasesrc.c(3187): gst_base_src_loop (): /GstPipeline:pipeline0/GstUDPSrc:udpsrc0:
streaming stopped, reason not-negotiated (-4)

And pushing GST_CAPS level to 5 and beyond doesn’t shed much light:

...
0:00:00.056854369  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.056915462  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
0:00:00.056951165  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstpad.c:2777:gst_pad_get_current_caps:<capsfilter1:sink> get current pad caps (NULL)
0:00:00.057021466  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstpad.c:2777:gst_pad_get_current_caps:<capsfilter1:src> get current pad caps (NULL)
0:00:00.057074827  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.057114432  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
0:00:00.057159972  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstpad.c:2777:gst_pad_get_current_caps:<rtpsbcdepay0:sink> get current pad caps (NULL)
0:00:00.057259099  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.057300234  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
0:00:00.057340273  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.057376474  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
ERROR: from element /GstPipeline:pipeline0/GstUDPSrc:udpsrc0: Internal data stream error.
Additional debug info:
../libs/gst/base/gstbasesrc.c(3187): gst_base_src_loop (): /GstPipeline:pipeline0/GstUDPSrc:udpsrc0:
streaming stopped, reason not-negotiated (-4)
0:00:00.057609681  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
Execution ended after 0:00:00.017514610
Setting pipeline to NULL ...
0:00:00.057653198  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
0:00:00.057700026  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.057735476  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1
0:00:00.057780758  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3196:gst_pad_query_accept_caps:<sbcdec0:sink> accept caps of audio/x-sbc, parsed=(boolean)true, channels=(int)1, rate=(int)44100
0:00:00.057821103  3883 0x7f1eb8000b70 DEBUG               GST_CAPS gstutils.c:3202:gst_pad_query_accept_caps:<sbcdec0:sink> query returned 1

So, my take is that the caps logs are not the tool of choice to untangle a misnegotiation. But what is ?

Jafeth.Garcia · April 7, 2025, 8:19pm

Hi, I think I found the issue. Usually after the depay of the rtp stream a parse step is necessary in order for the decoder to be able to process the data. This is just something needed with the protocol. Adding the sbcparse plugin should allow the enconder to start streaming.

gst-launch-1.0 udpsrc port=5004 ! \
application/x-rtp,payload=96,clock-rate=44100 ! \
rtpsbcdepay ! sbcparse ! sbcdec ! audioconvert ! audioresample ! \
autoaudiosink

As you mentioned the logs from sbcdec are not helpful in figuring this out so this was mostly knowledge based.

Could you test this adding the sbcparse into your original pipeline as well?

ferrieux · April 8, 2025, 9:34pm

You nailed it ! Thanks a lot :))
As it turns out, I still get an error, but no longer in the caps neg: it is the Bluetooth part that somehow fails to acquire the transport. (That’s weird, as the low-level bluetooth monitor says things like “Acquire successful: fd 8 MTU 672:1008”… but I understand the GStreamer avdtXXX plugins go through the extra D-Bus bloatware; there might be dragons)

To get back to the topic: indeed you found it “from knowledge”. To be completely honest, by forcing a capsfilter with “parsed=true”, I did cheat a bit, ignoring an earlier warning about that missing property which did convey some meaning. However, the lesson for the Gstreamer design, is that this tiny bit of light was drowned in an ocean of irrelevant stuff, like channels=[1,2]. Possibly, the fault lies in the design of the SBC plugin series, which uses a single stream type audio/x-sbc (with or without parsed=true, which can mistakenly be “forced” by a capsfilter like I did). If instead they had defined two different (and not “castable”) types like audio/x-sbc-unparsed,audio/x-sbc, the message would have been unambiguous and any newbie like me would have understood that something like sbcparse was needed…

Anyway, thanks again !