GES 1.16.0, caps renegotiation problem

[David Ing]

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[David Ing]

For more context, I am attaching some dot files which illustrate the pipeline in these two states.

• immediately after READY -> PAUSED
• immediately after PAUSED -> PLAYING

You can view these *.dot files at http://www.webgraphviz.com/ (paste the file contents into the web page).  My version of graphviz (2.40.1) does not render these files properly.

I am also attaching a more complete log file (*.txt).

On Wed, Jul 24, 2019 at 8:56 AM David Ing <[hidden email]> wrote:

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Mathieu Duponchelle]

Regarding your first question, yes it is fortunately completely acceptable for caps to be
(re)negotiated in a PLAYING pipeline, if it was not then you could not dynamically update
pipelines, which is a feature GES obviously heavily relies on.

Regarding your second question, it looks like there might be some memory corruption going
on, as the expected format for the log message is:

    if (!gst_qtmux_caps_is_subset_full (qtmux, current_caps, caps)) {
      gst_caps_unref (current_caps);
      GST_WARNING_OBJECT (qtmux,
          "pad %s refused renegotiation to %" GST_PTR_FORMAT,
          GST_PAD_NAME (pad), caps);
      gst_object_unref (qtmux);
      return FALSE;
    }

Caps here are supposed to be displayed as a string, if they're not that means GST_IS_CAPS (caps)
failed, which is odd. More generally, qtmux only seems to support renegotiating the caps for an
input stream if the new caps are not a subset of the older ones, however I can't tell if the check
genuinely fails here because the new caps don't fulfill that condition, or because of the apparent
memory corruption.

On 7/24/19 5:56 PM, David Ing wrote:

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[David Ing]

Can anyone recommend some techniques for diagnosing heap corruption issues on Linux (Fedora 30)?

If I were on Windows I would use gflags (to set up guard pages) and windbg (for kernel-level debugging) but I don't know what is available on Linux.

On Wed, Jul 24, 2019 at 9:35 AM Mathieu Duponchelle <[hidden email]> wrote:

Regarding your first question, yes it is fortunately completely acceptable for caps to be
(re)negotiated in a PLAYING pipeline, if it was not then you could not dynamically update
pipelines, which is a feature GES obviously heavily relies on.

Regarding your second question, it looks like there might be some memory corruption going
on, as the expected format for the log message is:

    if (!gst_qtmux_caps_is_subset_full (qtmux, current_caps, caps)) {
      gst_caps_unref (current_caps);
      GST_WARNING_OBJECT (qtmux,
          "pad %s refused renegotiation to %" GST_PTR_FORMAT,
          GST_PAD_NAME (pad), caps);
      gst_object_unref (qtmux);
      return FALSE;
    }

Caps here are supposed to be displayed as a string, if they're not that means GST_IS_CAPS (caps)
failed, which is odd. More generally, qtmux only seems to support renegotiating the caps for an
input stream if the new caps are not a subset of the older ones, however I can't tell if the check
genuinely fails here because the new caps don't fulfill that condition, or because of the apparent
memory corruption.

On 7/24/19 5:56 PM, David Ing wrote:

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[Mathieu Duponchelle]

valgrind comes to mind, though you'll need to use the appropriate suppression files to get
a sensible result, see the commands used for example by gst-validate-launcher when running
a test with the -vg switch.

On 7/24/19 6:55 PM, David Ing wrote:

Can anyone recommend some techniques for diagnosing heap corruption issues on Linux (Fedora 30)?

If I were on Windows I would use gflags (to set up guard pages) and windbg (for kernel-level debugging) but I don't know what is available on Linux.

On Wed, Jul 24, 2019 at 9:35 AM Mathieu Duponchelle <[hidden email]> wrote:

Regarding your first question, yes it is fortunately completely acceptable for caps to be
(re)negotiated in a PLAYING pipeline, if it was not then you could not dynamically update
pipelines, which is a feature GES obviously heavily relies on.

Regarding your second question, it looks like there might be some memory corruption going
on, as the expected format for the log message is:

    if (!gst_qtmux_caps_is_subset_full (qtmux, current_caps, caps)) {
      gst_caps_unref (current_caps);
      GST_WARNING_OBJECT (qtmux,
          "pad %s refused renegotiation to %" GST_PTR_FORMAT,
          GST_PAD_NAME (pad), caps);
      gst_object_unref (qtmux);
      return FALSE;
    }

Caps here are supposed to be displayed as a string, if they're not that means GST_IS_CAPS (caps)
failed, which is odd. More generally, qtmux only seems to support renegotiating the caps for an
input stream if the new caps are not a subset of the older ones, however I can't tell if the check
genuinely fails here because the new caps don't fulfill that condition, or because of the apparent
memory corruption.

On 7/24/19 5:56 PM, David Ing wrote:

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

[David Ing]

It turns out that I had no heap corruption, but at least I learned how to use valgrind and google sanitizers.

I messed up the way Gstreamer logs were grafted into my logging system.  (I failed to realized that Gstreamer has a custom sprintf function.)

But the core issue remains.  I am going to start a new email thread to re-describe the issue from scratch.

On Wed, Jul 24, 2019 at 9:58 AM Mathieu Duponchelle <[hidden email]> wrote:

valgrind comes to mind, though you'll need to use the appropriate suppression files to get
a sensible result, see the commands used for example by gst-validate-launcher when running
a test with the -vg switch.

On 7/24/19 6:55 PM, David Ing wrote:

Can anyone recommend some techniques for diagnosing heap corruption issues on Linux (Fedora 30)?

If I were on Windows I would use gflags (to set up guard pages) and windbg (for kernel-level debugging) but I don't know what is available on Linux.

On Wed, Jul 24, 2019 at 9:35 AM Mathieu Duponchelle <[hidden email]> wrote:

Regarding your first question, yes it is fortunately completely acceptable for caps to be
(re)negotiated in a PLAYING pipeline, if it was not then you could not dynamically update
pipelines, which is a feature GES obviously heavily relies on.

Regarding your second question, it looks like there might be some memory corruption going
on, as the expected format for the log message is:

    if (!gst_qtmux_caps_is_subset_full (qtmux, current_caps, caps)) {
      gst_caps_unref (current_caps);
      GST_WARNING_OBJECT (qtmux,
          "pad %s refused renegotiation to %" GST_PTR_FORMAT,
          GST_PAD_NAME (pad), caps);
      gst_object_unref (qtmux);
      return FALSE;
    }

Caps here are supposed to be displayed as a string, if they're not that means GST_IS_CAPS (caps)
failed, which is odd. More generally, qtmux only seems to support renegotiating the caps for an
input stream if the new caps are not a subset of the older ones, however I can't tell if the check
genuinely fails here because the new caps don't fulfill that condition, or because of the apparent
memory corruption.

On 7/24/19 5:56 PM, David Ing wrote:

I am running a GESTimeline inside of a GstPipeline.  I am attaching an SVG file which illustrates the pipeline when it enters it's READY state.

Soon after the the pipeline begins PLAYING, the muxers receive a request to re-negotiate the caps.

My first question is:  Is it normal to re-negotiate caps after a pipeline is already playing?  (This doesn't seem right to me.)

My second question is:  How can I determine which element is trying to renegotiate the caps after the pipeline is already PLAYING?

BTW:  Here are the logs I see as it relates to the caps re-negotation error.

19-07-24T15:44:36.530562 INFO    pan CompositionJob.cpp:123 Pipeline state changed from PAUSED to PLAYING in 0.000 seconds.
19-07-24T15:44:36.925546 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.925725 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.927847 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000 A
19-07-24T15:44:36.932935 WARNING qtdemux qtdemux.c:6607 error: Internal data stream error.
19-07-24T15:44:36.933041 WARNING qtdemux qtdemux.c:6607 error: streaming stopped, reason not-negotiated (-4)
19-07-24T15:44:36.934955 ERROR   pan CompositionJob.cpp:282 GST_MESSAGE_ERROR received from element qtdemux5 at position 5465466666: Internal data stream error.
../gst-plugins-good/gst/isomp4/qtdemux.c(6607): gst_qtdemux_loop (): /GstPipeline:pipeline/GESTimeline:gestimeline0/GESVideoTrack:gesvideotrack0/NleComposition:video_nlecomposition1/GstBin:current-bin/NleSource:GESVideoUriSource:nlesource4/GstBin:videosrcbin/GstURIDecodeBin:uridecodebin2/GstDecodeBin:decodebin9/GstQTDemux:qtdemux5:
streaming stopped, reason not-negotiated (-4)

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel

_______________________________________________
gstreamer-devel mailing list
[hidden email]
https://lists.freedesktop.org/mailman/listinfo/gstreamer-devel