GES 1.16.0, caps renegotiation problem

David Ing ding at panopto.com
Wed Jul 24 16:35:05 UTC 2019 

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 <ding at panopto.com> 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)
>
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190724/285ea841/attachment-0001.html>
-------------- next part --------------
19-07-24T15:44:33.998323 INFO    pan CompositionJob.cpp:1328 Starting job.
19-07-24T15:44:34.187610 FIX     ges ges-smart-video-mixer.c:364 Stop dropping allocation query when it is not required anymore.
19-07-24T15:44:34.229784 WARNING ges-asset ges-asset.c:1055 Tried to create an Asset for type GESUriClip but no ->init method
19-07-24T15:44:34.230107 WARNING discoverer gstdiscoverer.c:2015 No URI to process
19-07-24T15:44:34.230878 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:34.231227 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:34.329614 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:34.329713 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:34.329790 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:35.505374 FIX     bin gstbin.c:4337 implement duration caching in GstBin again
19-07-24T15:44:35.676100 WARNING ges-asset ges-asset.c:1055 Tried to create an Asset for type GESUriClip but no ->init method
19-07-24T15:44:35.676333 WARNING discoverer gstdiscoverer.c:2015 No URI to process
19-07-24T15:44:35.676599 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:35.676782 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:35.678172 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:35.678243 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type uuid
19-07-24T15:44:35.678285 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:35.678346 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:35.914854 WARNING ges-asset ges-asset.c:1055 Tried to create an Asset for type GESUriClip but no ->init method
19-07-24T15:44:35.915090 WARNING discoverer gstdiscoverer.c:2015 No URI to process
19-07-24T15:44:35.915355 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:35.915537 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:35.917077 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:35.917148 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type uuid
19-07-24T15:44:35.917209 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:35.917284 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:36.053650 INFO    pan CompositionJob.cpp:1198 Including MP4 container /home/ding/github/panopto/panopto-core/Panopto/Media/Native/cmake-build-debug/Tests/Panopto.Native.Media.GTest/bin/test-scratch/2019-07-24T15-44-33.767605/CompositionTests/DevTest/c:\Panopto\scratch\c4e3f2c4-7fcb-4429-86bc-aa93013f1207\842850a6-2ab4-4f59-804d-aa7e016e4e02\71f6ddca-5535-4090-a714-aa7e016e4e0c-f022e0fe-8aaf-4668-9bbb-aa93013f1233.mp4
19-07-24T15:44:36.054029 INFO    pan CompositionJob.cpp:1198 Including MP4 container /home/ding/github/panopto/panopto-core/Panopto/Media/Native/cmake-build-debug/Tests/Panopto.Native.Media.GTest/bin/test-scratch/2019-07-24T15-44-33.767605/CompositionTests/DevTest/c:\Panopto\scratch\c4e3f2c4-7fcb-4429-86bc-aa93013f1207\842850a6-2ab4-4f59-804d-aa7e016e4e02\71f6ddca-5535-4090-a714-aa7e016e4e0c-a1d1e1bf-cf57-4c32-8a0f-aa93013f1233.mp4
19-07-24T15:44:36.054110 INFO    pan CompositionJob.cpp:1339 Saving timeline.xges in log folder.
19-07-24T15:44:36.054960 INFO    pan CompositionJob.cpp:1351 Starting monitor at interval of 1000 milliseconds.
19-07-24T15:44:36.055791 INFO    pan CompositionJob.cpp:123 Pipeline state changed from NULL to READY in 0.000 seconds.
19-07-24T15:44:36.062306 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.062543 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.064983 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.065283 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.066505 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:36.066629 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:36.066736 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:36.067681 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:36.067807 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type uuid
19-07-24T15:44:36.067861 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:36.067952 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:36.071734 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.071867 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.074842 WARNING audio-resampler audio-resampler.c:274 can't find exact taps
19-07-24T15:44:36.076428 WARNING audio-resampler audio-resampler.c:274 can't find exact taps
19-07-24T15:44:36.079053 FIX     basesink gstbasesink.c:3246 stream-start event without group-id. Consider implementing group-id handling in the upstream elements
19-07-24T15:44:36.079198 WARNING qtmux gstqtmux.c:2981 Robust muxing requires reserved-moov-update-period to be set
19-07-24T15:44:36.122258 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.284923 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.285257 WARNING basesrc gstbasesrc.c:3600 pad not activated yet
19-07-24T15:44:36.286866 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type iods
19-07-24T15:44:36.286958 WARNING qtdemux qtdemux_types.c:239 unknown QuickTime node type uuid
19-07-24T15:44:36.286995 WARNING qtdemux qtdemux.c:7792 length too long (196608 > 7)
19-07-24T15:44:36.287073 WARNING qtdemux qtdemux.c:3239 failed to find fragment defaults for stream 1
19-07-24T15:44:36.340796 WARNING GST_PADS gstpad.c:4230 could not send sticky events
19-07-24T15:44:36.521715 FIX     basesink gstbasesink.c:3246 stream-start event without group-id. Consider implementing group-id handling in the upstream elements
19-07-24T15:44:36.521847 WARNING qtmux gstqtmux.c:2981 Robust muxing requires reserved-moov-update-period to be set
19-07-24T15:44:36.521962 INFO    pan CompositionJob.cpp:123 Pipeline state changed from READY to PAUSED in 0.463 seconds.
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 0x7f7080003000A
19-07-24T15:44:36.925673 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000A
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 0x7f7080003000A
19-07-24T15:44:36.927973 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000A
19-07-24T15:44:36.928039 WARNING qtmux gstqtmux.c:5118 pad video_0 refused renegotiation to 0x7f7080003000A
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)
19-07-24T15:44:36.935319 ERROR   pan CompositionJob.cpp:303 Job failed after 00:00:02.936996.  It started at 2019-07-24T15:44:33.998299Z.  Last observed timeline position was 3456333333 / 318583000001
19-07-24T15:44:36.945219 ERROR   pan CompositionJob.cpp:313 Logged graph of pipeline to graph_000003_JobFailed.dot.
19-07-24T15:44:36.945505 ERROR   pan CompositionJob.cpp:324 Final timeline position was 4256333333
19-07-24T15:44:36.945606 ERROR   pan CompositionJob.cpp:327 Job failed (the bus sent GST_MESSAGE_ERROR).
19-07-24T15:44:36.945696 ERROR   pan CompositionJob.cpp:1393 PanErr=1
19-07-24T15:44:36.945788 ERROR   pan CompositionJob.cpp:1434 Job failed while last observed timeline position was 4256333333 / 318583000001
19-07-24T15:44:36.955856 ERROR   pan CompositionJob.cpp:1439 Logged graph of pipeline to graph_000004_JobEnded.dot
19-07-24T15:44:36.956112 ERROR   pan CompositionJob.cpp:1455 Final timeline position was 4256333333
19-07-24T15:44:38.957297 ERROR   pan CompositionJob.cpp:117 Got ASYNC value while changing pipeline from PLAYING to PAUSED.  Excpected SUCCESS or NO_PREROLL.
19-07-24T15:44:38.957377 WARNING pan CompositionJob.cpp:176 Pipeline did not shut down in the allowed time.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: graph_000002_PipelinePausedToPlaying.dot
Type: application/msword-template
Size: 103404 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190724/285ea841/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: graph_000001_PipelineReadyToPaused.dot
Type: application/msword-template
Size: 103555 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/gstreamer-devel/attachments/20190724/285ea841/attachment-0003.bin>

More information about the gstreamer-devel mailing list