• State
  • Locked Locked
  • Replies 19 replies
  • Subscribers 101 subscribers
  • Views 3786 views
  • Users 0 members are here
Support feedback
Options
Options
Related

This thread has been locked.

If you have a related question, please click the "Ask a related question" button in the top right corner. The newly created question will be automatically linked to this question.

SK-TDA4VM: gstreamer pipeline unable to play H.264 RTSP stream with v4l2h264dec and kmssink

Janardhan Thodeti
Prodigy 140 points
Part Number: SK-TDA4VM
Other Parts Discussed in Thread: DRA712

I'm trying to play H.264 RTSP stream from a network camera using below gstreamer pipeline on SK-TDA4VM,

gst-launch-1.0 -v --gst-debug=4 \
rtspsrc location=rtsp://$REMOTE/stream1 latency=0 protocols=udp \
! rtpjitterbuffer \
! queue \
! rtph264depay \
! queue \
! h264parse \
! queue \
! v4l2h264dec \
! queue \
! 'video/x-raw,format=NV16,width=(int)1920,height=(int)1080' \
! videoconvert \
! kmssink &

Log file "g4_dbg.log" is attached.

The same RTSP H.264 stream is playing with about 1 sec latency with playbin pipeline,

gst-launch-1.0 -v --gst-debug=4 \
playbin uri=rtsp://$REMOTE/stream1 uridecodebin0::source::latency=300 video-sink=kmssink

Log file "g2_play.log" is attached.

I would like to use the first pipeline for stream control parameters where as playbin does not provide. Please let me know what is missing with the first pipeline. 

Regards,

Janag4_dbg.logg2_play.log

  • 0
    Prodigy 100 points

    Hi,

    Some update on the issue.
    We have used a bit simpler pipeline that should be aslo more adequate to the input rtsp stream:
    GST_DEBUG="v4l2*:7" gst-launch-1.0 rtspsrc location=rtsp://10.0.1.2/stream1 ! rtph264depay ! h264parse ! v4l2h264dec ! 'video/x-raw,format=(string)NV12,width=(int)1920,height=(int)1280,framerate=30/1' ! kmssink

    It still doesn't work but we can see that it fails at caps negotiation (between h264parse and v4l2h264dec):
    0:00:04.429556624  1552 0xffff9c004370 DEBUG           v4l2videodec gstv4l2videodec.c:664:gst_v4l2_video_dec_handle_frame:<v4l2h264dec0> Possible decoded caps: EMPTY
    0:00:04.429571104  1552 0xffff9c004370 ERROR           v4l2videodec gstv4l2videodec.c:753:gst_v4l2_video_dec_handle_frame:<v4l2h264dec0> not negotiated

    Comparing to the working pipeline that utilizes playbin plugin (gst_log_v4_pass.txt) we can see that in the failing scenario (gst_log_v4_fail.txt) a stripped format is set for v4l2h264dec:

    0:00:00.469655465  1552 0xffff9c004370 DEBUG           v4l2videodec gstv4l2videodec.c:223:gst_v4l2_video_dec_set_format:<v4l2h264dec0> Setting format: video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, parsed=(boolean)true

    while on passing one:

    0:00:00.516680376  1710 0xffff8c004370 DEBUG           v4l2videodec gstv4l2videodec.c:223:gst_v4l2_video_dec_set_format:<v4l2h264dec0> Setting format: video/x-h264, stream-format=(string)byte-stream, alignment=(string)au, level=(string)5, profile=(string)main, pixel-aspect-ratio=(fraction)1/1, width=(int)1920, height=(int)1280, framerate=(fraction)30/1, interlace-mode=(string)progressive, chroma-format=(string)4:2:0, bit-depth-luma=(uint)8, bit-depth-chroma=(uint)8, parsed=(boolean)true

    also reading of these capabilities for sink pad happens earlier for the failing case:

    0:00:00.053443816  1552     0x15b7cec0 DEBUG           v4l2videodec gstv4l2videodec.c:868:gst_v4l2_video_dec_sink_getcaps:<v4l2h264dec0> Returning sink caps video/x-h264, width=(int)[ 1, 32768 ], height=(int)[ 1, 32768 ], framerate=(fraction)[ 0/1, 2147483647/1 ], stream-format=(string)byte-stream, alignment=(string)au

    while on passing:
    0:00:00.516581449  1710 0xffff8c004370 DEBUG           v4l2videodec gstv4l2videodec.c:868:gst_v4l2_video_dec_sink_getcaps:<v4l2h264dec0> Returning sink caps video/x-h264, width=(int)1920, height=(int)1280, framerate=(fraction)30/1, pixel-aspect-ratio=(fraction)1/1, stream-format=(string)byte-stream, alignment=(string)au, colorimetry=(string){ bt601, smpte240m, bt709, 2:4:5:2, 2:4:5:3, 1:4:7:1, 2:4:7:1, 2:4:12:8, bt2020, 2:0:0:0 }, parsed=(boolean)true, level=(string)5, profile=(string)main, interlace-mode=(string)progressive, chroma-format=(string)4:2:0, bit-depth-luma=(uint)8, bit-depth-chroma=(uint)8

    We suspect that gst_v4l2_video_dec_sink_getcaps starts too early in the failing scenario and on a different thread.

    Of course, playbin introduces many other components to the pipeline (pipeline_PAUSED_PLAYING_playbin.pdf) but after adding some of them (as well as with queue elements) did not change anything.

    gst-launch-1.0 playbin uri=rtsp://10.0.1.2/stream1 uridecodebin0::source::latency=300 video-sink=kmssink

    Could you please help to analyze the problem?

    BR,
    Szymon

    gst_log_v4_fail.txtgst_log_v4_pass.txtpipeline_PAUSED_PLAYING_playbin.pdf

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    https://gstreamer.freedesktop.org/documentation/tutorials/basic/debugging-tools.html#getting-pipeline-graphs

    Please check the above link, which tells how to dump the gstreamer pipeline to a dot file

    GST_DEBUG_DUMP_DOT_DIR=playbin_dump gst-launch-1.0 -v --gst-debug=4 playbin uri=rtsp://$REMOTE/stream1 uridecodebin0::source::latency=300 video-sink=kmssink

    Above will generate some dot files in the specified directory

    You can run below command to visualize dot files as png

    dot -Tpng input.dot > output.png


    with this you can find out exact pipeline generated by playbin, which works

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi,

    Sorry, but we did not ask how to generate a graphic pipeline and we already have provided that pipeline to help you analyze the problem (please see pipeline_PAUSED_PLAYING_playbin.pdf attachment in my previous comment).

    BR,

    Szymon

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    Can you please try below pipeline which uses sw decoder, so that we can be sure that the issue is with v4l2h264dec

    gst-launch-1.0 rtspsrc location=rtsp://10.24.69.105:8555/test ! rtph264depay ! h264parse ! avdec_h264 ! video/x-raw, format=I420 ! videoconvert ! kmssink sync=false driver-name=tidss

    By the way we are not able to reproduce the issue at our end
    below pipeline works for us 

    gst-launch-1.0 rtspsrc location=rtsp://10.24.69.105:8555/test ! rtph264depay ! h264parse ! v4l2h264dec ! video/x-raw, format=NV12 ! kmssink sync=false driver-name=tidss

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi Rahul,

    SW decoder also has some issue with our camera stream (1920x1280 NV12). Please find logs attached.

    gst-launch-1.0 rtspsrc location=rtsp://10.0.1.2/stream1 protocols=udp ! rtph264depay ! h264parse ! avdec_h264 ! 'video/x-raw,format=(string)NV12' ! videoconvert ! kmssink

    Some noteworthy logs:

    0:00:09.101458665   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-raw, format=(string)I420, width=(int)1920, height=(int)1280, interlace-mode=(string)progressive, multiview-mode=(string)mono, multiview-flags=(GstVideoMultiviewFlagsSet)0:ffffffff:/right-view-first/left-flipped/left-flopped/right-flipped/right-flopped/half-aspect/mixed-mono, pixel-aspect-ratio=(fraction)1/1, chroma-site=(string)mpeg2, colorimetry=(string)1:3:5:1, framerate=(fraction)30/1
    0:00:09.101568965   836 0xffff800036d0 WARN                GST_PADS gstpad.c:4231:gst_pad_peer_query:<avdec_h264-0:src> could not send sticky events

    The format in caps is I420 instead of NV12.

    At the end we can see endless logs like below:

    0:00:20.260195545   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:3406:gst_video_decoder_decode_frame:<avdec_h264-0> flow error not-negotiated
    0:00:20.592921915   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:1365:gst_video_decoder_sink_event:<avdec_h264-0> received event 20510, tag
    0:00:20.592969725   928 0xffff74002b70 INFO            videodecoder gstvideodecoder.c:1312:gst_video_decoder_sink_event_default:<avdec_h264-0> upstream tags: taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;
    0:00:20.592991195   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:818:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> upstream : taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;
    0:00:20.593004935   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:819:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> decoder  : (NULL)
    0:00:20.593016175   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:820:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> mode     : 3
    0:00:20.593038540   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:826:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> merged   : taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;

    Fullscreen avdec_h264.txt Download 
    Progress: (open) Opening Stream
Progress: (connect) Connecting to rtsp://10.0.1.2/stream1
Progress: (open) Retrieving server options
0:00:03.384961565   836 0xaaaaf48b5800 INFO                 rtspsrc gstrtspsrc.c:7788:gst_rtspsrc_retrieve_sdp:<rtspsrc0> Now using version: 1.0
Progress: (open) Retrieving media info
0:00:03.387038085   836 0xaaaaf48b5800 INFO      GST_PLUGIN_LOADING gstplugin.c:902:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstudp.so" loaded
0:00:03.387079775   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "udpsrc"
0:00:03.387335380   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstBaseSrc@0xffff8c019d60> adding pad 'src'
0:00:03.387491400   836 0xaaaaf48b5800 INFO                  udpsrc gstudpsrc.c:1420:gst_udpsrc_open:<udpsrc0> setting udp buffer of 524288 bytes
0:00:03.387512315   836 0xaaaaf48b5800 INFO                  udpsrc gstudpsrc.c:1439:gst_udpsrc_open:<udpsrc0> forcibly setting udp buffer of 524288 bytes
0:00:03.719828225   836 0xaaaaf48b5800 INFO                  udpsrc gstudpsrc.c:1459:gst_udpsrc_open:<udpsrc0> have udp buffer of 524288 bytes
0:00:03.719874640   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsrc0> completed state change to READY
0:00:03.719892280   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc0> notifying about state-changed NULL to READY (VOID_PENDING pending)
0:00:03.720286235   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "udpsrc"
0:00:03.720351545   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstBaseSrc@0xffff8c01a670> adding pad 'src'
0:00:03.720501460   836 0xaaaaf48b5800 INFO                  udpsrc gstudpsrc.c:1459:gst_udpsrc_open:<udpsrc1> have udp buffer of 114688 bytes
0:00:03.720533935   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsrc1> completed state change to READY
0:00:03.720548780   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc1> notifying about state-changed NULL to READY (VOID_PENDING pending)
Progress: (request) SETUP stream 0
0:00:03.722400945   836 0xaaaaf48b5800 INFO      GST_PLUGIN_LOADING gstplugin.c:902:_priv_gst_plugin_load_file_for_registry: plugin "/usr/lib/gstreamer-1.0/libgstrtpmanager.so" loaded
0:00:03.722437270   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:360:gst_element_factory_create: creating element "rtpbin" named "manager"
0:00:03.722947440   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<manager> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:03.722966995   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<manager> notifying about state-changed NULL to READY (PAUSED pending)
0:00:03.723021150   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<manager> continue state change READY to PAUSED, final PAUSED
0:00:03.723042475   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<manager> completed state change to PAUSED
0:00:03.723057340   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<manager> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:03.723175150   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'recv_rtp_sink_0' in element "manager"
0:00:03.723201205   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "rtpsession"
0:00:03.723758515   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "rtpssrcdemux"
0:00:03.723878445   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpSsrcDemux@0xaaaaf4a4ce70> adding pad 'sink'
0:00:04.052942660   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpSsrcDemux@0xaaaaf4a4ce70> adding pad 'rtcp_sink'
0:00:04.052971685   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "rtpstorage"
0:00:04.053118910   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpStorage@0xaaaaf4ac2b40> adding pad 'src'
0:00:04.053135940   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpStorage@0xaaaaf4ac2b40> adding pad 'sink'
0:00:04.053313385   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpssrcdemux0> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:04.053330320   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpssrcdemux0> notifying about state-changed NULL to READY (PAUSED pending)
0:00:04.053378810   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpssrcdemux0> continue state change READY to PAUSED, final PAUSED
0:00:04.053401435   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpssrcdemux0> completed state change to PAUSED
0:00:04.053416305   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpssrcdemux0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:04.053466030   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpsession0> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:04.053481650   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpsession0> notifying about state-changed NULL to READY (PAUSED pending)
0:00:04.053506855   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpsession0> continue state change READY to PAUSED, final PAUSED
0:00:04.053522455   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpsession0> completed state change to PAUSED
0:00:04.053535140   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpsession0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:04.053561935   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpstorage0> committing state from NULL to READY, pending PAUSED, next PAUSED
0:00:04.053577380   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpstorage0> notifying about state-changed NULL to READY (PAUSED pending)
0:00:04.053611940   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpstorage0> continue state change READY to PAUSED, final PAUSED
0:00:04.053631980   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpstorage0> completed state change to PAUSED
0:00:04.386017850   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpstorage0> notifying about state-changed READY to PAUSED (VOID_PENDING pending)
0:00:04.386060265   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'recv_rtp_sink' in element "rtpsession0"
0:00:04.386120540   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpsession0> adding pad 'recv_rtp_sink'
0:00:04.386157990   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpsession0> adding pad 'recv_rtp_src'
0:00:04.386274970   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link recv_rtp_sink_0:proxypad0 and rtpsession0:recv_rtp_sink
0:00:04.386294220   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked recv_rtp_sink_0:proxypad0 and rtpsession0:recv_rtp_sink, successful
0:00:04.386306400   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.386333975   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<manager> adding pad 'recv_rtp_sink_0'
0:00:04.386358265   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpsession0:recv_rtp_src
0:00:04.386374495   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpstorage0:sink
0:00:04.386401705   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpsession0:recv_rtp_src and rtpstorage0:sink
0:00:04.386428725   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:4237:gst_pad_peer_query:<rtpstorage0:src> pad has no peer
0:00:04.386451075   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpsession0:recv_rtp_src and rtpstorage0:sink, successful
0:00:04.386462310   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.386485215   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpstorage0:src
0:00:04.386498200   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpssrcdemux0:sink
0:00:04.386514555   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpstorage0:src and rtpssrcdemux0:sink
0:00:04.386528805   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpstorage0:src and rtpssrcdemux0:sink, successful
0:00:04.386538880   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.719160090   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'recv_rtcp_sink_0' in element "manager"
0:00:04.719187170   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'recv_rtcp_sink' in element "rtpsession0"
0:00:04.719243580   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpsession0> adding pad 'recv_rtcp_sink'
0:00:04.719278725   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpsession0> adding pad 'sync_src'
0:00:04.719305900   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpsession0:sync_src
0:00:04.719319230   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpssrcdemux0:rtcp_sink
0:00:04.719338995   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpsession0:sync_src and rtpssrcdemux0:rtcp_sink
0:00:04.719354760   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpsession0:sync_src and rtpssrcdemux0:rtcp_sink, successful
0:00:04.719365720   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.719415635   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link recv_rtcp_sink_0:proxypad1 and rtpsession0:recv_rtcp_sink
0:00:04.719431490   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked recv_rtcp_sink_0:proxypad1 and rtpsession0:recv_rtcp_sink, successful
0:00:04.719441885   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.719461550   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<manager> adding pad 'recv_rtcp_sink_0'
0:00:04.719491005   836 0xaaaaf48b5800 INFO                 rtspsrc gstrtspsrc.c:3953:gst_rtspsrc_stream_configure_manager:<rtspsrc0> configure bandwidth in session 0xaaaaf4b38f00
0:00:04.719512995   836 0xaaaaf48b5800 INFO                 rtspsrc gstrtspsrc.c:3958:gst_rtspsrc_stream_configure_manager:<rtspsrc0> setting AS: 2000000.000000
0:00:04.719611575   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad udpsrc0:src
0:00:04.719635415   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link udpsrc0:src and manager:recv_rtp_sink_0
0:00:04.719650930   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked udpsrc0:src and manager:recv_rtp_sink_0, successful
0:00:04.719661695   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:04.719673300   836 0xaaaaf48b5800 INFO               GST_EVENT gstpad.c:5812:gst_pad_send_event_unchecked:<udpsrc0:src> Received event on flushing pad. Discarding
0:00:05.052231385   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad udpsrc1:src
0:00:05.052258135   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link udpsrc1:src and manager:recv_rtcp_sink_0
0:00:05.052273725   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked udpsrc1:src and manager:recv_rtcp_sink_0, successful
0:00:05.052284055   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:05.052295715   836 0xaaaaf48b5800 INFO               GST_EVENT gstpad.c:5812:gst_pad_send_event_unchecked:<udpsrc1:src> Received event on flushing pad. Discarding
0:00:05.052647930   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "udpsink"
0:00:05.052936645   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstBaseSink@0xffff8c043cc0> adding pad 'sink'
0:00:05.062948940   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "fakesrc"
0:00:05.063163605   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstBaseSrc@0xffff8c048150> adding pad 'src'
0:00:05.063243620   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstutils.c:1771:gst_element_link_pads_full: trying to link element fakesrc0:src to element udpsink0:sink
0:00:05.063259285   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad fakesrc0:src
0:00:05.063272210   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad udpsink0:sink
0:00:05.063314280   836 0xaaaaf48b5800 INFO                GST_PADS gstutils.c:1587:prepare_link_maybe_ghosting: fakesrc0 and udpsink0 in same bin, no need for ghost pads
0:00:05.063339710   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link fakesrc0:src and udpsink0:sink
0:00:05.063356060   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked fakesrc0:src and udpsink0:sink, successful
0:00:05.063367320   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:05.063380360   836 0xaaaaf48b5800 INFO               GST_EVENT gstpad.c:5812:gst_pad_send_event_unchecked:<fakesrc0:src> Received event on flushing pad. Discarding
0:00:05.063731725   836 0xaaaaf48b5800 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "udpsink"
0:00:05.063819080   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstBaseSink@0xffff8c046d30> adding pad 'sink'
0:00:05.064386505   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsink1> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:05.396423225   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink1> notifying about state-changed NULL to READY (PLAYING pending)
0:00:05.396455515   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsink1> continue state change READY to PAUSED, final PLAYING
0:00:05.396484540   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsink1> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:05.396498375   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink1> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:05.396514180   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsink1> continue state change PAUSED to PLAYING, final PLAYING
0:00:05.396526550   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsink1> completed state change to PLAYING
0:00:05.396539360   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:05.396588250   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad udpsink1:sink
0:00:05.396610905   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'send_rtcp_src_0' in element "manager"
0:00:05.396637785   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'send_rtcp_src' in element "rtpsession0"
0:00:05.396697645   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpsession0> adding pad 'send_rtcp_src'
0:00:05.396765895   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpsession0:send_rtcp_src and send_rtcp_src_0:proxypad2
0:00:05.396784485   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpsession0:send_rtcp_src and send_rtcp_src_0:proxypad2, successful
0:00:05.396796155   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:05.396822170   836 0xaaaaf48b5800 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<manager> adding pad 'send_rtcp_src_0'
0:00:05.396851215   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link manager:send_rtcp_src_0 and udpsink1:sink
0:00:05.396866295   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked manager:send_rtcp_src_0 and udpsink1:sink, successful
0:00:05.396876575   836 0xaaaaf48b5800 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
Progress: (open) Opened Stream
Setting pipeline to PLAYING ...
0:00:05.397170270   836 0xaaaaf4899600 INFO               GST_EVENT gstevent.c:1449:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:05.729547535   836 0xaaaaf4899600 INFO                     bin gstbin.c:2783:gst_bin_do_latency_func:<pipeline0> configured latency of 0:00:00.000000000
0:00:05.729592655   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<kmssink0> current READY pending PAUSED, desired next PLAYING
0:00:05.729609625   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2959:gst_bin_change_state_func:<pipeline0> child 'kmssink0' is changing state asynchronously to PLAYING
0:00:05.729627140   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<videoconvert0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:05.729643755   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<videoconvert0> completed state change to PLAYING
0:00:05.729658840   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<videoconvert0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:05.729681735   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'videoconvert0' changed state to 4(PLAYING) successfully
0:00:05.729699330   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<capsfilter0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:05.729713395   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<capsfilter0> completed state change to PLAYING
0:00:05.729726780   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<capsfilter0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:05.729745070   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'capsfilter0' changed state to 4(PLAYING) successfully
0:00:05.729761935   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<avdec_h264-0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:05.729776610   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<avdec_h264-0> completed state change to PLAYING
0:00:05.729789315   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<avdec_h264-0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:05.729807335   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'avdec_h264-0' changed state to 4(PLAYING) successfully
0:00:05.729824050   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<h264parse0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:05.729838500   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<h264parse0> completed state change to PLAYING
0:00:05.729851285   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<h264parse0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.062615850   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'h264parse0' changed state to 4(PLAYING) successfully
0:00:06.062636200   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<rtph264depay0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:06.062652090   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtph264depay0> completed state change to PLAYING
0:00:06.062666260   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtph264depay0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.062684420   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'rtph264depay0' changed state to 4(PLAYING) successfully
0:00:06.062801650   836 0xaaaaf48b5800 INFO                    task gsttask.c:312:gst_task_func:<task0> Task going to paused
0:00:06.062823790   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'udpsink1' changed state to 4(PLAYING) successfully
0:00:06.062843380   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'udpsink0' changed state to 4(PLAYING) successfully
0:00:06.062862465   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'manager' changed state to 4(PLAYING) successfully
0:00:06.062877990   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'fakesrc0' changed state to 4(PLAYING) successfully
0:00:06.062893090   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'udpsrc0' changed state to 4(PLAYING) successfully
0:00:06.062907900   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<rtspsrc0> child 'udpsrc1' changed state to 4(PLAYING) successfully
0:00:06.062939445   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtspsrc0> completed state change to PLAYING
0:00:06.062941715   836 0xaaaaf48b5800 INFO                    task gsttask.c:314:gst_task_func:<task0> Task resume from paused
0:00:06.062957980   836 0xaaaaf4899600 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtspsrc0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.062977455   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsink0> completed state change to NULL
0:00:06.062979935   836 0xaaaaf4899600 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<pipeline0> child 'rtspsrc0' changed state to 4(PLAYING) successfully
0:00:06.062998190   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<fakesrc0> completed state change to NULL
New clock: GstSystemClock
0:00:06.395751875   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsink0> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:06.395773960   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink0> notifying about state-changed NULL to READY (PLAYING pending)
0:00:06.395802895   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsink0> continue state change READY to PAUSED, final PLAYING
0:00:06.395830795   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsink0> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:06.395845150   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink0> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:06.395862550   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsink0> continue state change PAUSED to PLAYING, final PLAYING
0:00:06.395874930   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsink0> completed state change to PLAYING
Progress: (request) Sending PLAY request
0:00:06.395887840   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsink0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.395952165   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<fakesrc0> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:06.395967130   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<fakesrc0> notifying about state-changed NULL to READY (PLAYING pending)
0:00:06.395985275   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<fakesrc0> continue state change READY to PAUSED, final PLAYING
0:00:06.396022980   836 0xaaaaf48b5800 INFO                 basesrc gstbasesrc.c:1373:gst_base_src_do_seek:<fakesrc0> seeking: bytes segment start=0, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0, base=0, position 0, duration -1
0:00:06.396058115   836 0xaaaaf48b5800 INFO                    task gsttask.c:460:gst_task_set_lock: setting stream lock 0xffff8c01d930 on task 0xaaaaf4ac2cb0
0:00:06.396072505   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:6159:gst_pad_start_task:<fakesrc0:src> created task 0xaaaaf4ac2cb0
0:00:06.396148225   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<fakesrc0> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:06.396164280   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<fakesrc0> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:06.396230420   836 0xffff8c035590 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'sink' in element "fakesrc0"
0:00:06.396212490   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<fakesrc0> continue state change PAUSED to PLAYING, final PLAYING
0:00:06.728811055   836 0xffff8c035590 FIXME                default gstutils.c:3980:gst_pad_create_stream_id_internal:<fakesrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
0:00:06.728812940   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<fakesrc0> completed state change to PLAYING
0:00:06.728841745   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<fakesrc0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.728927965   836 0xffff8c035590 INFO               GST_EVENT gstevent.c:900:gst_event_new_segment: creating segment event bytes segment start=0, offset=0, stop=-1, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0, base=0, position 0, duration -1
0:00:06.728952020   836 0xffff8c035590 INFO                 basesrc gstbasesrc.c:2962:gst_base_src_loop:<fakesrc0> marking pending DISCONT
Progress: (request) Sending PLAY request
0:00:06.729191375   836 0xffff8c035590 INFO                 basesrc gstbasesrc.c:2853:gst_base_src_loop:<fakesrc0> pausing after gst_base_src_get_range() = eos
0:00:06.729226270   836 0xffff8c035590 INFO                    task gsttask.c:312:gst_task_func:<fakesrc0:src> Task going to paused
0:00:06.730097420   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<rtpssrcdemux0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:06.730124280   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpssrcdemux0> completed state change to PLAYING
0:00:06.730139075   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpssrcdemux0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.730186290   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<manager> child 'rtpssrcdemux0' changed state to 4(PLAYING) successfully
0:00:06.730207355   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<rtpstorage0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:06.730222290   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpstorage0> completed state change to PLAYING
0:00:06.730235525   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpstorage0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:06.730264610   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<manager> child 'rtpstorage0' changed state to 4(PLAYING) successfully
0:00:06.730284290   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2503:gst_bin_element_set_state:<rtpsession0> current PAUSED pending VOID_PENDING, desired next PLAYING
0:00:07.062046060   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpsession0> completed state change to PLAYING
0:00:07.062072935   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpsession0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:07.062131950   836 0xaaaaf48b5800 INFO              GST_STATES gstbin.c:2952:gst_bin_change_state_func:<manager> child 'rtpsession0' changed state to 4(PLAYING) successfully
0:00:07.062155435   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<manager> completed state change to PLAYING
0:00:07.062169425   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<manager> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:07.062232865   836 0xaaaaf48b5800 INFO                 basesrc gstbasesrc.c:1373:gst_base_src_do_seek:<udpsrc0> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:07.062272965   836 0xaaaaf48b5800 INFO                    task gsttask.c:460:gst_task_set_lock: setting stream lock 0xaaaaf4ac1db0 on task 0xaaaaf4ac2dd0
0:00:07.062287190   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:6159:gst_pad_start_task:<udpsrc0:src> created task 0xaaaaf4ac2dd0
0:00:07.062407045   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsrc0> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:07.062426465   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc0> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:07.062497720   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'sink' in element "udpsrc0"
0:00:07.062484350   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsrc0> continue state change PAUSED to PLAYING, final PLAYING
0:00:07.062586295   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsrc0> completed state change to PLAYING
0:00:07.062600580   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:07.062705855   836 0xaaaaf48b5800 INFO                 basesrc gstbasesrc.c:1373:gst_base_src_do_seek:<udpsrc1> seeking: time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:07.062739475   836 0xaaaaf48b5800 INFO                    task gsttask.c:460:gst_task_set_lock: setting stream lock 0xffff8c01c210 on task 0xaaaaf4ac2ef0
0:00:07.062738675   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, profile-level-id=(string)4D4032, sprop-parameter-sets=(string)"Z01AMo2NQDwBQ/4C3AQEBQAAAwPoAADqYOhgAehAAACAvvrvLjQwAPQgAABAX313lwo\=\,aO44gA\=\=", a-tool=(string)"RTSP\ Server:\ Ambarella\ RTSP\ Server\ v202004022020.04.02", a-type=(string)broadcast, x-qt-text-nam=(string)"Session\ streamed\ by\ \"Ambarella\ RTSP\ Server\"", x-qt-text-inf=(string)stream1, a-cliprect=(string)"0\,0\,1280\,1920", a-framerate=(string)30.000000, ssrc=(uint)10158426, clock-base=(uint)0, seqnum-base=(uint)0, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1
0:00:07.395040320   836 0xaaaaf48b5800 INFO                GST_PADS gstpad.c:6159:gst_pad_start_task:<udpsrc1:src> created task 0xaaaaf4ac2ef0
0:00:07.395711920   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:900:gst_event_new_segment: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:07.395859195   836 0xffff8c0356d0 INFO                 basesrc gstbasesrc.c:2962:gst_base_src_loop:<udpsrc0> marking pending DISCONT
0:00:07.396356075   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<udpsrc1> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:07.396395565   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc1> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:07.396557305   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<udpsrc1> continue state change PAUSED to PLAYING, final PLAYING
0:00:07.396585635   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<udpsrc1> completed state change to PLAYING
0:00:07.396547440   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, profile-level-id=(string)4D4032, sprop-parameter-sets=(string)"Z01AMo2NQDwBQ/4C3AQEBQAAAwPoAADqYOhgAehAAACAvvrvLjQwAPQgAABAX313lwo\=\,aO44gA\=\=", a-tool=(string)"RTSP\ Server:\ Ambarella\ RTSP\ Server\ v202004022020.04.02", a-type=(string)broadcast, x-qt-text-nam=(string)"Session\ streamed\ by\ \"Ambarella\ RTSP\ Server\"", x-qt-text-inf=(string)stream1, a-cliprect=(string)"0\,0\,1280\,1920", a-framerate=(string)30.000000, ssrc=(uint)10158426, clock-base=(uint)0, seqnum-base=(uint)0, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1
0:00:07.396630405   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpssrcdemux0> adding pad 'src_10158426'
0:00:07.396650505   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpssrcdemux0> adding pad 'rtcp_src_10158426'
0:00:07.396679080   836 0xffff8c0356d0 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "rtpjitterbuffer"
0:00:07.728146695   836 0xaaaaf48b5800 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<udpsrc1> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:07.728315645   836 0xffff8c035720 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'sink' in element "udpsrc1"
0:00:07.728511575   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpJitterBuffer@0xffff80023c40> adding pad 'src'
0:00:07.728544105   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpJitterBuffer@0xffff80023c40> adding pad 'sink'
Progress: (request) Sent PLAY request
0:00:07.728573730   836 0xffff8c0356d0 INFO     GST_ELEMENT_FACTORY gstelementfactory.c:363:gst_element_factory_create: creating element "rtpptdemux"
0:00:07.728776390   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<GstRtpPtDemux@0xffff800270c0> adding pad 'sink'
0:00:07.728775155   836 0xffff8c035720 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtcp
0:00:07.728889150   836 0xffff8c035720 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtcp, ssrc=(uint)10158426
0:00:07.728951910   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstutils.c:1771:gst_element_link_pads_full: trying to link element rtpjitterbuffer0:src to element rtpptdemux0:sink
0:00:07.728969455   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpjitterbuffer0:src
0:00:07.728982995   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpptdemux0:sink
0:00:07.728996855   836 0xffff8c0356d0 INFO                GST_PADS gstutils.c:1587:prepare_link_maybe_ghosting: rtpjitterbuffer0 and rtpptdemux0 in same bin, no need for ghost pads
0:00:07.729032410   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpjitterbuffer0:src and rtpptdemux0:sink
0:00:07.729049885   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpjitterbuffer0:src and rtpptdemux0:sink, successful
0:00:07.729060900   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:07.729074840   836 0xffff8c0356d0 INFO               GST_EVENT gstpad.c:5812:gst_pad_send_event_unchecked:<rtpjitterbuffer0:src> Received event on flushing pad. Discarding
0:00:07.729102655   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpptdemux0> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:07.729118120   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpptdemux0> notifying about state-changed NULL to READY (PLAYING pending)
0:00:07.729164445   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpptdemux0> continue state change READY to PAUSED, final PLAYING
0:00:08.061256370   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpptdemux0> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:08.061281745   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpptdemux0> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:08.061325405   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpptdemux0> continue state change PAUSED to PLAYING, final PLAYING
0:00:08.061339715   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpptdemux0> completed state change to PLAYING
0:00:08.061354060   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpptdemux0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:08.061384430   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpjitterbuffer0> committing state from NULL to READY, pending PLAYING, next PAUSED
0:00:08.061398430   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpjitterbuffer0> notifying about state-changed NULL to READY (PLAYING pending)
0:00:08.061423870   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpjitterbuffer0> continue state change READY to PAUSED, final PLAYING
0:00:08.061591510   836 0xffff8c0356d0 INFO                    task gsttask.c:460:gst_task_set_lock: setting stream lock 0xffff8c04cad0 on task 0xffff8c037a70
0:00:08.061611015   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:6159:gst_pad_start_task:<rtpjitterbuffer0:src> created task 0xffff8c037a70
0:00:08.061726795   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2660:gst_element_continue_state:<rtpjitterbuffer0> committing state from READY to PAUSED, pending PLAYING, next PLAYING
0:00:08.061761040   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpjitterbuffer0> notifying about state-changed READY to PAUSED (PLAYING pending)
0:00:08.061801015   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2668:gst_element_continue_state:<rtpjitterbuffer0> continue state change PAUSED to PLAYING, final PLAYING
0:00:08.061820710   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2688:gst_element_continue_state:<rtpjitterbuffer0> completed state change to PLAYING
0:00:08.061834500   836 0xffff8c0356d0 INFO              GST_STATES gstelement.c:2588:_priv_gst_element_state_changed:<rtpjitterbuffer0> notifying about state-changed PAUSED to PLAYING (VOID_PENDING pending)
0:00:08.061869685   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpssrcdemux0:src_10158426
0:00:08.061884990   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpjitterbuffer0:sink
0:00:08.394356635   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpssrcdemux0:src_10158426 and rtpjitterbuffer0:sink
0:00:08.394386705   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpssrcdemux0:src_10158426 and rtpjitterbuffer0:sink, successful
0:00:08.394398710   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:08.394446790   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:928:gst_element_get_static_pad: found pad rtpssrcdemux0:rtcp_src_10158426
0:00:08.394464500   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:925:gst_element_get_static_pad: no such pad 'sink_rtcp' in element "rtpjitterbuffer0"
0:00:08.394531995   836 0xffff8c0356d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpjitterbuffer0> adding pad 'sink_rtcp'
0:00:08.394593105   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpssrcdemux0:rtcp_src_10158426 and rtpjitterbuffer0:sink_rtcp
0:00:08.394610125   836 0xffff8c0356d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpssrcdemux0:rtcp_src_10158426 and rtpjitterbuffer0:sink_rtcp, successful
0:00:08.394620560   836 0xffff8c0356d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:08.394798540   836 0xffff8c0356d0 INFO         rtpjitterbuffer rtpjitterbuffer.c:795:rtp_jitter_buffer_calculate_pts: resync to time 0:00:01.998559120, rtptime 0:00:00.000000000
0:00:08.394978545   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtp, media=(string)video, payload=(int)96, clock-rate=(int)90000, encoding-name=(string)H264, packetization-mode=(string)1, profile-level-id=(string)4D4032, sprop-parameter-sets=(string)"Z01AMo2NQDwBQ/4C3AQEBQAAAwPoAADqYOhgAehAAACAvvrvLjQwAPQgAABAX313lwo\=\,aO44gA\=\=", a-tool=(string)"RTSP\ Server:\ Ambarella\ RTSP\ Server\ v202004022020.04.02", a-type=(string)broadcast, x-qt-text-nam=(string)"Session\ streamed\ by\ \"Ambarella\ RTSP\ Server\"", x-qt-text-inf=(string)stream1, a-cliprect=(string)"0\,0\,1280\,1920", a-framerate=(string)30.000000, ssrc=(uint)10158426, clock-base=(uint)0, seqnum-base=(uint)0, npt-start=(guint64)0, play-speed=(double)1, play-scale=(double)1
0:00:08.395033105   836 0xffff800036d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtpptdemux0> adding pad 'src_96'
0:00:08.395109465   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtpptdemux0:src_96 and recv_rtp_src_0_10158426_96:proxypad3
0:00:08.395139515   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtpptdemux0:src_96 and recv_rtp_src_0_10158426_96:proxypad3, successful
0:00:08.395152670   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:08.395206020   836 0xffff800036d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<manager> adding pad 'recv_rtp_src_0_10158426_96'

(gst-launch-1.0:836): GStreamer-WARNING **: 11:35:14.338: ../gstreamer-1.16.3/gst/gstpad.c:4549:gst_pad_push_data:<rtpsession0:sync_src> Got data flow before segment event

(gst-launch-1.0:836): GStreamer-WARNING **: 11:35:14.664: ../gstreamer-1.16.3/gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<rtpssrcdemux0:rtcp_sink> Got data flow before segment event

(gst-launch-1.0:836): GStreamer-WARNING **: 11:35:14.664: ../gstreamer-1.16.3/gst/gstpad.c:4549:gst_pad_push_data:<rtpssrcdemux0:rtcp_src_10158426> Got data flow before segment event
0:00:08.727588460   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link manager:recv_rtp_src_0_10158426_96 and recv_rtp_src_0_10158426_96:proxypad4
0:00:08.727612775   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked manager:recv_rtp_src_0_10158426_96 and recv_rtp_src_0_10158426_96:proxypad4, successful
0:00:08.727625395   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event

(gst-launch-1.0:836): GStreamer-WARNING **: 11:35:14.664: ../gstreamer-1.16.3/gst/gstpad.c:4296:gst_pad_chain_data_unchecked:<rtpjitterbuffer0:sink_rtcp> Got data flow before segment event
0:00:08.727693905   836 0xffff800036d0 INFO        GST_ELEMENT_PADS gstelement.c:671:gst_element_add_pad:<rtspsrc0> adding pad 'recv_rtp_src_0_10158426_96'
0:00:08.727730525   836 0xffff800036d0 INFO            GST_PIPELINE grammar.y:520:gst_parse_found_pad: trying delayed linking one pad some pad of GstRTSPSrc named rtspsrc0 to some pad of GstRtpH264Depay named rtph264depay0
0:00:08.727754605   836 0xffff800036d0 INFO        GST_ELEMENT_PADS gstutils.c:1771:gst_element_link_pads_full: trying to link element rtspsrc0:(any) to element rtph264depay0:(any)
0:00:08.727774650   836 0xffff800036d0 INFO                GST_PADS gstutils.c:1034:gst_pad_check_link: trying to link rtspsrc0:recv_rtp_src_0_10158426_96 and rtph264depay0:sink
0:00:08.727827880   836 0xffff800036d0 INFO                GST_PADS gstutils.c:1587:prepare_link_maybe_ghosting: rtspsrc0 and rtph264depay0 in same bin, no need for ghost pads
0:00:08.727850470   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2377:gst_pad_link_prepare: trying to link rtspsrc0:recv_rtp_src_0_10158426_96 and rtph264depay0:sink
0:00:08.727899430   836 0xffff800036d0 INFO                GST_PADS gstpad.c:2585:gst_pad_link_full: linked rtspsrc0:recv_rtp_src_0_10158426_96 and rtph264depay0:sink, successful
0:00:08.727913415   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:1579:gst_event_new_reconfigure: creating reconfigure event
0:00:08.728047720   836 0xffff800036d0 FIXME               basesink gstbasesink.c:3246:gst_base_sink_default_event:<kmssink0> stream-start event without group-id. Consider implementing group-id handling in the upstream elements
0:00:08.729087880   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)014d4032ffe10032674d40328d8d403c0143fe02dc04040500000303e80000ea60e86001e840000080befaef2e343000f4200000405f7d77970a01000468ee3880, level=(string)5, profile=(string)main
0:00:08.729482935   836 0xffff8c0356d0 WARN         rtpjitterbuffer rtpjitterbuffer.c:587:calculate_skew: delta - skew: 0:00:01.033798218 too big, reset skew
0:00:09.061287235   836 0xffff800036d0 INFO               h264parse gsth264parse.c:1914:gst_h264_parse_update_src_caps:<h264parse0> resolution changed 1920x1280
0:00:09.061317765   836 0xffff800036d0 INFO               h264parse gsth264parse.c:1938:gst_h264_parse_update_src_caps:<h264parse0> pixel aspect ratio has been changed 1/1
0:00:09.061337245   836 0xffff800036d0 INFO               h264parse gsth264parse.c:1975:gst_h264_parse_update_src_caps:<h264parse0> PAR 1/1
0:00:09.061366495   836 0xffff800036d0 INFO               baseparse gstbaseparse.c:4068:gst_base_parse_set_latency:<h264parse0> min/max latency 0:00:00.033333333, 0:00:00.033333333
0:00:09.061939540   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)014d4032ffe10032674d40328d8d403c0143fe02dc04040500000303e80000ea60e86001e840000080befaef2e343000f4200000405f7d77970a01000468ee3880, level=(string)5, profile=(string)main, pixel-aspect-ratio=(fraction)1/1, width=(int)1920, height=(int)1280, framerate=(fraction)30/1, interlace-mode=(string)progressive, chroma-format=(string)4:2:0, bit-depth-luma=(uint)8, bit-depth-chroma=(uint)8, parsed=(boolean)true
0:00:09.063322645   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:900:gst_event_new_segment: creating segment event time segment start=0:00:01.998559120, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:01.998559120, position 0:00:01.998559120, duration 99:99:99.999999999
Redistribute latency...
0:00:09.063603965   836 0xaaaaf4899600 INFO               GST_EVENT gstevent.c:1449:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:09.063640740   836 0xaaaaf4899600 INFO                     bin gstbin.c:2783:gst_bin_do_latency_func:<pipeline0> configured latency of 0:00:00.000000000
0:00:09.064522940   836 0xffff800036d0 INFO               h264parse gsth264parse.c:1975:gst_h264_parse_update_src_caps:<h264parse0> PAR 1/1
0:00:09.064577085   836 0xffff800036d0 INFO               baseparse gstbaseparse.c:4068:gst_base_parse_set_latency:<h264parse0> min/max latency 0:00:00.033333333, 0:00:00.033333333
0:00:09.064771070   836 0xffff800036d0 INFO            videodecoder gstvideodecoder.c:1312:gst_video_decoder_sink_event_default:<avdec_h264-0> upstream tags: taglist, video-codec=(string)"H.264\ \(Main\ Profile\)";
0:00:09.065408175   836 0xffff800036d0 INFO                   libav :0:: Reinit context to 1920x1280, pix_fmt: yuvj420p
0:00:09.101458665   836 0xffff800036d0 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event video/x-raw, format=(string)I420, width=(int)1920, height=(int)1280, interlace-mode=(string)progressive, multiview-mode=(string)mono, multiview-flags=(GstVideoMultiviewFlagsSet)0:ffffffff:/right-view-first/left-flipped/left-flopped/right-flipped/right-flopped/half-aspect/mixed-mono, pixel-aspect-ratio=(fraction)1/1, chroma-site=(string)mpeg2, colorimetry=(string)1:3:5:1, framerate=(fraction)30/1
0:00:09.101568965   836 0xffff800036d0 WARN                GST_PADS gstpad.c:4231:gst_pad_peer_query:<avdec_h264-0:src> could not send sticky events
Redistribute latency...
0:00:09.102009340   836 0xaaaaf4899600 INFO               GST_EVENT gstevent.c:1449:gst_event_new_latency: creating latency event 0:00:00.000000000
0:00:09.102055145   836 0xaaaaf4899600 INFO                     bin gstbin.c:2783:gst_bin_do_latency_func:<pipeline0> configured latency of 0:00:00.000000000
0:00:09.105759530   836 0xffff800036d0 INFO            videodecoder gstvideodecoder.c:3184:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> First buffer since flush took 0:00:06.057347910 to produce
0:00:09.336023530   836 0xffff8c035680 INFO               GST_EVENT gstevent.c:820:gst_event_new_caps: creating caps event application/x-rtcp
0:00:09.432791310   836 0xffff8c035680 INFO               GST_EVENT gstevent.c:900:gst_event_new_segment: creating segment event time segment start=0:00:00.000000000, offset=0:00:00.000000000, stop=99:99:99.999999999, rate=1.000000, applied_rate=1.000000, flags=0x00, time=0:00:00.000000000, base=0:00:00.000000000, position 0:00:00.000000000, duration 99:99:99.999999999
0:00:09.627552205   836 0xffff800036d0 INFO            videodecoder gstvideodecoder.c:1312:gst_video_decoder_sink_event_default:<avdec_h264-0> upstream tags: taglist, video-codec=(string)"H.264\ \(Main\ Profile\)", minimum-bitrate=(uint)869280, maximum-bitrate=(uint)869280, bitrate=(uint)7840416;


Debug logs:
0:00:20.260131670   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:3168:gst_video_decoder_clip_and_push_buf:<avdec_h264-0> pushing buffer 0xffff70065ea0 of size 3686400, PTS 0:00:01.513347969, dur 0:00:00.033333333
0:00:20.260195545   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:3406:gst_video_decoder_decode_frame:<avdec_h264-0> flow error not-negotiated
0:00:20.592921915   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:1365:gst_video_decoder_sink_event:<avdec_h264-0> received event 20510, tag
0:00:20.592969725   928 0xffff74002b70 INFO            videodecoder gstvideodecoder.c:1312:gst_video_decoder_sink_event_default:<avdec_h264-0> upstream tags: taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;
0:00:20.592991195   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:818:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> upstream : taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;
0:00:20.593004935   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:819:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> decoder  : (NULL)
0:00:20.593016175   928 0xffff74002b70 LOG             videodecoder gstvideodecoder.c:820:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> mode     : 3
0:00:20.593038540   928 0xffff74002b70 DEBUG           videodecoder gstvideodecoder.c:826:gst_video_decoder_create_merged_tags_event:<avdec_h264-0> merged   : taglist, video-codec=(string)"H.264\ \(High\ Profile\)", minimum-bitrate=(uint)1369200, maximum-bitrate=(uint)15331440, bitrate=(uint)8075525;

    BR,

    Szymon

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    Below is a simple script that we use to generate rtsp streams
    Same pipeline:
    gst-launch-1.0 rtspsrc location="rtsp://$IP:8554/stream1" latency=67 protocols=udp drop-on-latency=true max-dropout-time=134 max-misorder-time=67 ! rtph264depay ! h264parse ! v4l2h264dec ! 'video/x-raw,format=(string)NV12' ! kmssink connector-id=39 plane-id=49

    Works for us with the rtsp server that we are using
    Please try this out to see what might be the difference between the stream you are using and this one
    rtsp_server.zip

    Regards

    Rahul T R

  • 0 in reply to Rahul Ravikumar
    TI__Guru 51481 points

    Rahul,

    The zip file is coming with 0KB (i.e. nothing in the file).  Could you post to the shared CDDS site?

    https://cdds.ext.ti.com/ematrix/common/emxNavigator.jsp?objectId=28670.42872.25234.63668

    Also, could you comment on the analysis of the stream provided by Szymon (as mentioned on the call today); note also that this stream works on the J6 Entry / DRA712 as well?

    John 

  • 0 in reply to John H. Gardner
    TI__Guru 51481 points

    Szymon, 

    RSTP file has been uploaded now to the link above.  Also Rahul is still working the analysis of your stream.  I'll continue to track.

    John 

  • 0 in reply to John H. Gardner
    Prodigy 100 points

    Hi John,

    Still, the archive uploaded to CDDS is empty.

  • 0 in reply to Szymon Mielczarek
    TI__Guru 51481 points

    Szymon, 

    Confirmed. I think our email firewall stripped out the content when Rahul sent me the zip file.   I’ve just given Rahul editor privileges to that folder (below) and asked that he post directly. 

    US - https://cdds.ext.ti.com/ematrix/common/emxNavigator.jsp?objectId=28670.42872.25234.63668

    John 

  • 0 in reply to John H. Gardner
    TI__Expert 4158 points

    Hi Szymon,

    Please find the content in the below link

    CDDS: Texas Instruments Collaborative Design & Delivery System

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi Rahul,

    Thank you.

    Anyway, please focus on analyzing the stream we have provided through CDDS. There are many differences between the stream you are playing and the one our camera is providing.

    Our: Stream #0:0: Video: h264 (Main), yuvj420p(pc, bt709, progressive), 1920x1280 [SAR 1:1 DAR 3:2], 30 fps, 30 tbr, 90k tbn, 60 tbc

    Your: Stream #0:0: Video: h264 (High), yuv420p(progressive), 1280x720, 30 fps, 30 tbr, 90k tbn, 60 tbc

    In addition, in our stream video, full and differential frames are sent alternately while in common stream the full frame is sent sporadically. This can be a potential issue for v4l decoder.

    BR,

    Szymon

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    Is it possible to share the bit stream
    in a binary file?
    by testing the bit stream using filesrc
    we can rule out any rtp handshake related
    issues

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi Rahul,

    We have extracted our video stream to mp4 file. We can upload it to CDDS but it may not be useful for you (please read further). This issue is not reproducible with filesrc. It needs to be tested with RTSP.

    We can play our mp4 video when streaming using your RTSP server (python) but even using your test.mp4 video we can reproduce the issue with "not negotiated" caps (please see my initial comment) by just adding framerate to video/x-raw component, please check on your side:

    GST_DEBUG=3 gst-launch-1.0 rtspsrc location="rtsp://$IP:8554/stream1" latency=67 protocols=udp drop-on-latency=true max-dropout-time=134 max-misorder-time=67 ! rtph264depay ! h264parse ! v4l2h264dec ! 'video/x-raw,format=(string)NV12,framerate=30/1' ! kmssink connector-id=39 plane-id=49

    0:00:00.699329590   595 0xffff98001b70 ERROR           v4l2videodec gstv4l2videodec.c:753:gst_v4l2_video_dec_handle_frame:<v4l2h264dec0> not negotiated

    if we remove framerate from our pipeline below when streaming from camera, vxe-vxd decoder driver crashes, please see attached file:

    Fullscreen v4l2_crash.txt Download 
    Progress: (request) Sending PLAY request
Progress: (request) Sending PLAY request
0:00:00.731708990   546 0xffff90031a30 FIXME                default gstutils.c:3980:gst_pad_create_stream_id_internal:<fakesrc0:src> Creating random stream-id, consider implementing a deterministic way of creating a stream-id
Progress: (request) Sent PLAY request
0:00:03.198792355   546 0xffff78003770 FIXME               basesink gstbasesink.c:3246:gst_base_sink_default_event:<kmssink0> stream-start event without group[ 1152.048539] img_dec 4300000.video-decoder: get_header_info preparsed data is null 0
-id. Consider implementing group-id handling in the upstream elements
0:00:03.207444240   546 0xffff78003770 WARN                    v4l2 gstv4l2object.c:4292:gst_v4l2_object_probe_caps:<v4l2h264dec0:src> Failed to probe pixel aspect ratio with VIDIOC_CROPCAP: Invalid argument
0:00:0[ 1152.084702] [USERSID=0x00000008] UNSUPPORTED[HW]: TRANSFORM PIXEL FORMAT FROM 400 TO 420
3.208806595   546 0xffff78003770 WARN   [ 1152.084711] [USERSID=0x00000008] UNSUPPORTED[HW]: CODED PICTURE LUMA BIT DEPTH 0 [RANGE: 8->10 for VDEC_STD_H264]
                 v4l2 gstv4l2object.c:4292:gst_v4l2_object_[ 1152.092816] [USERSID=0x00000008] UNSUPPORTED[HW]: CODED PICTURE SIZE 0 x 0 [MIN: 64 x 16]
[ 1152.108648] ------------[ cut here ]------------
probe_caps:<v4l2h264dec0:src> Failed to probe pixel aspect [ 1152.126902] WARNING: CPU: 1 PID: 556 at drivers/media/platform/vxe-vxd/decoder/core.c:579 core_check_decoder_support.isra.0+0x134/0x170 [vxd_dec]
ratio with VIDIOC_CROPCAP: Invalid argument
0:00:03.225079880  Modules linked in: xt_tcpudp can_raw can bluetooth ecdh_generic ecc rfkill algif_hash ecb iptable_filter ip_tables x_tables aes_neon_bs aes_neon_blk algif_skcipher af_alg xhci_plat_hcd xhci_hcd rpmsg_char omap_rng rng_core irq_pruss_intc pru_rproc icss_iep cdns3 udc_core roles cdns_csi2rx v4l2_fwnode usbcore usb_common crct10dif_ce phy_can_transceiver ti_k3_r5_remoteproc pvrsrvkm(O) cdns_mhdp8546 pci_endpoint_test pruss sa2ul ti_k3_dsp_remoteproc sha512_generic vxe_enc authenc virtio_rpmsg_bus vxd_dec cdns_dphy videobuf2_dma_sg j721e_csi2rx cdns3_ti v4l2_mem2mem videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common m_can_platform m_can can_dev rti_wdt overlay sch_fq_codel rpmsg_kdrv_switch cryptodev(O) ipv6
[331m  546 0xffff78003770 WARN           [ 1152.215891] CPU: 1 PID: 556 Comm: rtpjitterbuffer Tainted: G           O      5.10.120-g8e186f71dd #1
 v4l2videodec gstv4l2videodec.c:813:gst_v4l2_video_dec_decide_al[ 1152.230629] Hardware name: Texas Instruments J721E SK (DT)
location:<v4l2h264dec0> Duration invalid, not setting laten[ 1152.241645] pstate: 60000005 (nZCv daif -PAN -UAO -TCO BTYPE=--)
cy
0:00:03.248219190   546 0xffff78003770 WA[ 1152.253203] pc : core_check_decoder_support.isra.0+0x134/0x170 [vxd_dec]
RN          v4l2bufferpool gstv4l2bufferpool.c:820:gst[ 1152.265417] lr : core_check_decoder_support.isra.0+0xf0/0x170 [vxd_dec]
_v4l2_buffer_pool_start:<v4l2h264dec0:pool:src> Uncertain o[ 1152.277546] sp : ffff8000137f3930
r not enough buffers, enabling copy threshold
[ 1152.286392] x29: ffff8000137f3950 x28: 0000000040045612 
[ 1152.295759] x27: ffff0008136766d8 x26: ffff000811684000 
[ 1152.301056] x25: ffff8000137f39b4 x24: ffff0008116c2000 
[ 1152.306351] x23: ffff000803006c08 x22: ffff000811684270 
[ 1152.311646] x21: ffff000811684028 x20: ffff0008037e8000 
[ 1152.316943] x19: ffff8000137f3ae8 x18: 0000000000000010 
[ 1152.322240] x17: 0000000000000000 x16: 0000000000000000 
[ 1152.327535] x15: ffff0008037e8538 x14: 4f43203a5d57485b 
[ 1152.332830] x13: 444554524f505055 x12: 414d554c20455255 
[ 1152.338127] x11: ffff80001157e0b8 x10: ffff800011566078 
[ 1152.343424] x9 : ffff800010181380 x8 : 0000000000017fe8 
[ 1152.348721] x7 : c0000000ffffefff x6 : 0000000000000001 
[ 1152.354016] x5 : 0000000000000000 x4 : ffff00087f7d3ab8 
[ 1152.359313] x3 : ffff00087f7e2b88 x2 : a6f99ce0a1ed7900 
[ 1152.364609] x1 : 0000000000000400 x0 : 0000000000000016 
[ 1152.369907] Call trace:
[ 1152.372358]  core_check_decoder_support.isra.0+0x134/0x170 [vxd_dec]
[ 1152.378703]  core_stream_submit_unit+0x144/0xef0 [vxd_dec]
[ 1152.384181]  device_run+0x258/0x388 [vxd_dec]
[ 1152.388532]  v4l2_m2m_try_run+0x8c/0x140 [v4l2_mem2mem]
[ 1152.393742]  v4l2_m2m_streamon+0x6c/0x88 [v4l2_mem2mem]
[ 1152.398951]  v4l2_m2m_ioctl_streamon+0x20/0x30 [v4l2_mem2mem]
[ 1152.404689]  v4l_streamon+0x2c/0x38
[ 1152.408164]  __video_do_ioctl+0x18c/0x3f0
[ 1152.412158]  video_usercopy+0x194/0x6e0
[ 1152.415978]  video_ioctl2+0x20/0x68
[ 1152.419452]  v4l2_ioctl+0x48/0x68
[ 1152.422758]  __arm64_sys_ioctl+0xb0/0xf8
[ 1152.426670]  el0_svc_common.constprop.0+0x80/0x1d0
[ 1152.431445]  do_el0_svc+0x2c/0x98
[ 1152.434750]  el0_svc+0x20/0x30
[ 1152.437792]  el0_sync_handler+0xb0/0xb8
[ 1152.441614]  el0_sync+0x180/0x1c0
[ 1152.444916] ---[ end trace d281d803392a430a ]---
[ 1152.449606] ------------[ cut here ]------------
[ 1152.454244] WARNING: CPU: 1 PID: 556 at drivers/media/platform/vxe-vxd/decoder/core.c:2637 core_stream_submit_unit+0x57c/0xef0 [vxd_dec]
[ 1152.466472] Modules linked in: xt_tcpudp can_raw can bluetooth ecdh_generic ecc rfkill algif_hash ecb iptable_filter ip_tables x_tables aes_neon_bs aes_neon_blk algif_skcipher af_alg xhci_plat_hcd xhci_hcd rpmsg_char omap_rng rng_core irq_pruss_intc pru_rproc icss_iep cdns3 udc_core roles cdns_csi2rx v4l2_fwnode usbcore usb_common crct10dif_ce phy_can_transceiver ti_k3_r5_remoteproc pvrsrvkm(O) cdns_mhdp8546 pci_endpoint_test pruss sa2ul ti_k3_dsp_remoteproc sha512_generic vxe_enc authenc virtio_rpmsg_bus vxd_dec cdns_dphy videobuf2_dma_sg j721e_csi2rx cdns3_ti v4l2_mem2mem videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common m_can_platform m_can can_dev rti_wdt overlay sch_fq_codel rpmsg_kdrv_switch cryptodev(O) ipv6
[ 1152.531491] CPU: 1 PID: 556 Comm: rtpjitterbuffer Tainted: G        W  O      5.10.120-g8e186f71dd #1
[ 1152.540686] Hardware name: Texas Instruments J721E SK (DT)
[ 1152.546155] pstate: 60000005 (nZCv daif -PAN -UAO -TCO BTYPE=--)
[ 1152.552158] pc : core_stream_submit_unit+0x57c/0xef0 [vxd_dec]
[ 1152.557984] lr : core_stream_submit_unit+0x144/0xef0 [vxd_dec]
[ 1152.563798] sp : ffff8000137f3a10
[ 1152.567098] x29: ffff8000137f3a10 x28: 0000000040045612 
[ 1152.572395] x27: ffff0008136766d8 x26: ffff000811684000 
[ 1152.577691] x25: ffff8000137f3ae8 x24: ffff0008116c2000 
[ 1152.582988] x23: ffff000813676eb8 x22: ffff0008136766d8 
[ 1152.588285] x21: ffff0008037e8000 x20: 0000000003000001 
[ 1152.593580] x19: ffff0008031e24f0 x18: 0000000000000010 
[ 1152.598875] x17: 0000000000000000 x16: 0000000000000000 
[ 1152.604171] x15: ffff0008037e8538 x14: 4f43203a5d57485b 
[ 1152.609468] x13: 444554524f505055 x12: 414d554c20455255 
[ 1152.614765] x11: ffff80001157e0b8 x10: ffff800011566078 
[ 1152.620060] x9 : ffff800010181380 x8 : 0000000000017fe8 
[ 1152.625356] x7 : c0000000ffffefff x6 : 0000000000000001 
[ 1152.630652] x5 : 0000000000000000 x4 : ffff00087f7d3ab8 
[ 1152.635948] x3 : 0000000100000000 x2 : a6f99ce0a1ed7900 
[ 1152.641244] x1 : 0000000000000000 x0 : 0000000000000016 
[ 1152.646540] Call trace:
[ 1152.648989]  core_stream_submit_unit+0x57c/0xef0 [vxd_dec]
[ 1152.654466]  device_run+0x258/0x388 [vxd_dec]
[ 1152.658813]  v4l2_m2m_try_run+0x8c/0x140 [v4l2_mem2mem]
[ 1152.664022]  v4l2_m2m_streamon+0x6c/0x88 [v4l2_mem2mem]
[ 1152.669232]  v4l2_m2m_ioctl_streamon+0x20/0x30 [v4l2_mem2mem]
[ 1152.674968]  v4l_streamon+0x2c/0x38
[ 1152.678442]  __video_do_ioctl+0x18c/0x3f0
[ 1152.682437]  video_usercopy+0x194/0x6e0
[ 1152.686257]  video_ioctl2+0x20/0x68
[ 1152.689731]  v4l2_ioctl+0x48/0x68
[ 1152.693036]  __arm64_sys_ioctl+0xb0/0xf8
[ 1152.696948]  el0_svc_common.constprop.0+0x80/0x1d0
[ 1152.701723]  do_el0_svc+0x2c/0x98
[ 1152.705027]  el0_svc+0x20/0x30
[ 1152.708068]  el0_sync_handler+0xb0/0xb8
[ 1152.711891]  el0_sync+0x180/0x1c0
[ 1152.715192] ---[ end trace d281d803392a430b ]---
[ 1152.719937] [USERSID=0x00000008] Unable to get the current picture from Decoder context
[ 1152.719999] ------------[ cut here ]------------
[ 1152.732603] WARNING: CPU: 1 PID: 556 at drivers/media/platform/vxe-vxd/decoder/decoder.c:2817 decoder_stream_process_unit+0x4a4/0x988 [vxd_dec]
[ 1152.745437] Modules linked in: xt_tcpudp can_raw can bluetooth ecdh_generic ecc rfkill algif_hash ecb iptable_filter ip_tables x_tables aes_neon_bs aes_neon_blk algif_skcipher af_alg xhci_plat_hcd xhci_hcd rpmsg_char omap_rng rng_core irq_pruss_intc pru_rproc icss_iep cdns3 udc_core roles cdns_csi2rx v4l2_fwnode usbcore usb_common crct10dif_ce phy_can_transceiver ti_k3_r5_remoteproc pvrsrvkm(O) cdns_mhdp8546 pci_endpoint_test pruss sa2ul ti_k3_dsp_remoteproc sha512_generic vxe_enc authenc virtio_rpmsg_bus vxd_dec cdns_dphy videobuf2_dma_sg j721e_csi2rx cdns3_ti v4l2_mem2mem videobuf2_dma_contig videobuf2_memops videobuf2_v4l2 videobuf2_common m_can_platform m_can can_dev rti_wdt overlay sch_fq_codel rpmsg_kdrv_switch cryptodev(O) ipv6
[ 1152.810453] CPU: 1 PID: 556 Comm: rtpjitterbuffer Tainted: G        W  O      5.10.120-g8e186f71dd #1
[ 1152.819648] Hardware name: Texas Instruments J721E SK (DT)
[ 1152.825118] pstate: 40000005 (nZcv daif -PAN -UAO -TCO BTYPE=--)
[ 1152.831118] pc : decoder_stream_process_unit+0x4a4/0x988 [vxd_dec]
[ 1152.837291] lr : decoder_stream_process_unit+0x49c/0x988 [vxd_dec]
[ 1152.843450] sp : ffff8000137f3990
[ 1152.846751] x29: ffff8000137f3990 x28: 0000000040045612 
[ 1152.852048] x27: ffff0008136766d8 x26: ffff000811684000 
[ 1152.857344] x25: ffff000813676000 x24: ffff0008116c2000 
[ 1152.862641] x23: ffff000813676eb8 x22: ffff0008037e8000 
[ 1152.867938] x21: ffff0008031e2568 x20: ffff000811685000 
[ 1152.873234] x19: 0000000000000007 x18: 0000000000000010 
[ 1152.878531] x17: 0000000000000000 x16: 0000000000000000 
[ 1152.883826] x15: ffff0008037e8538 x14: ffffffffffffffff 
[ 1152.889121] x13: ffff8000116eb680 x12: ffff8000116eb2b4 
[ 1152.894418] x11: ffff80001157e0b8 x10: ffff800011566078 
[ 1152.899713] x9 : ffff800010181380 x8 : 0000000000017fe8 
[ 1152.905010] x7 : c0000000ffffefff x6 : 0000000000000001 
[ 1152.910307] x5 : 0000000000000000 x4 : ffff00087f7d3ab8 
[ 1152.915603] x3 : ffff00087f7e2b88 x2 : a6f99ce0a1ed7900 
[ 1152.920900] x1 : 0000000000000000 x0 : 0000000000000007 
[ 1152.926196] Call trace:
[ 1152.928644]  decoder_stream_process_unit+0x4a4/0x988 [vxd_dec]
[ 1152.934468]  core_stream_submit_unit+0xb8/0xef0 [vxd_dec]
[ 1152.939858]  device_run+0x2a4/0x388 [vxd_dec]
[ 1152.944205]  v4l2_m2m_try_run+0x8c/0x140 [v4l2_mem2mem]
[ 1152.949414]  v4l2_m2m_streamon+0x6c/0x88 [v4l2_mem2mem]
[ 1152.954624]  v4l2_m2m_ioctl_streamon+0x20/0x30 [v4l2_mem2mem]
[ 1152.960361]  v4l_streamon+0x2c/0x38
[ 1152.963835]  __video_do_ioctl+0x18c/0x3f0
[ 1152.967830]  video_usercopy+0x194/0x6e0
[ 1152.971652]  video_ioctl2+0x20/0x68
[ 1152.975126]  v4l2_ioctl+0x48/0x68
[ 1152.978430]  __arm64_sys_ioctl+0xb0/0xf8
[ 1152.982344]  el0_svc_common.constprop.0+0x80/0x1d0
[ 1152.987119]  do_el0_svc+0x2c/0x98
[ 1152.990423]  el0_svc+0x20/0x30
[ 1152.993463]  el0_sync_handler+0xb0/0xb8
[ 1152.997285]  el0_sync+0x180/0x1c0
[ 1153.000587] ---[ end trace d281d803392a430c ]---


    GST_DEBUG=3 gst-launch-1.0 rtspsrc location=rtsp://10.0.1.2/stream1 ! rtph264depay ! h264parse ! v4l2h264dec ! 'video/x-raw,format=(string)NV12,width=(int)1920,height=(int)1280,framerate=30/1' ! kmssink

    Now, initially we have reported that with "playbin" plugin the video works but with above pipeline not ("not negotiated" or decoder crash).
    We've compared RTP related packets gathered using Wireshark for both scenarios and we cannot see any differences in RTP handshaking. Why playbin pipeline works then?

    For "not negotiated" issue we suspect that gst_v4l2_video_dec_sink_getcaps starts too early in the failing scenario and on a different thread.

    We've also compared RTP packets from your python and camera RTSP server. There are some additional TCP packets for Camera server but RTSP handshaking looks the same.
    We do not understand why J7 (SDK8) behaves differently with your server. Maybe there is a timing issue or it drops some initial packets.
    As it was mentioned, the same video stream from our camera works on J6 (SDK6) and RTSP server on camera side is compliant with specific RFC for RTSP and RTP H.264 Payload.

    Did you already try to use our RTSP server with camera emulator?

    BR,
    Szymon

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    I was able to stream from camera emulator on target
    using SW decoder, please check the below pipeline

    gst-launch-1.0 rtspsrc location=rtsp://10.24.69.105:554/stream1 latency=0 proxy-id=None proxy-pw=None ! rtph264depay ! h264parse ! avdec_h264 ! videoconvert ! kmssink sync=false

    We are facing issues with v4l2h264dec, which we are debugging,
    But using SW decoder should unblock you for now.

    Please try the above pipeline and let me know if it works at your end

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    TI__Expert 4158 points

    Hi Szymon,

    Got the issue 

    Below is the working pipeline with v4l2h264dec !

    gst-launch-1.0 rtspsrc location=rtsp://10.24.69.105:554/stream1 latency=0 proxy-id=None proxy-pw=None ! rtph264depay ! video/x-h264, stream-format=avc ! h264parse ! v4l2h264dec ! kmssink sync=false

    I still need to understand why we have specify the stream-format in sink caps of h264parse, if we don't specify, it negotiates
    the avc stream as byte-stream and HW decoder was getting error when reading the header and crashing

    Hope the above pipeline solves the issue

    Regards
    Rahul T R  

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi Rahul,

    Thank you. I can confirm that after this change the pipeline is working but ... usually, after several minutes the video is frozen with below output:

    [ 6456.767091] [USERSID=0x00000022] [TID 0x02248FA3] MMCO error accured when processing the current frame. May have corruption
    [ 6456.767116] decoder_picture_decoded : 4319 err_flags: 0x200
    [ 6456.783886] img_dec 4300000.video-decoder: _img_mem_free: found mapping for buffer 2 (size 249856)
    0:20:26.136082430  2472 0xffff6c003720 WARN           v4l2allocator gstv4l2allocator.c:1370:gst_v4l2_allocator_dqbuf:<v4l2h264dec0:pool:src:allocator> V4L2 provided buffer has bytesused 0 which is too small to include data_offset 0

    As we already mentioned, the same issue was present with playbin.

    BR,

    Szymon

  • 0 in reply to Szymon Mielczarek
    TI__Expert 4158 points

    Hi Szymon,

    it was mentioned that this happened at specific point in some given stream
    Can you please share that stream, so that it will be easier for us to reproduce and debug this issue

    Regards
    Rahul T R

  • 0 in reply to Rahul Ravikumar
    Prodigy 100 points

    Hi Rahul,

    With attached mp4 the streaming should fail around 2nd second even playing with your RTSP server.

    /cfs-file/__key/communityserver-discussions-components-files/791/test_2D00_stopper_2D00_5s.mp4

    BR,

    Szymon