Internal data stream error when streaming from RTSP source.

[msjoshi]

I'm using the producer library in a Docker container to stream from RTSP source. The RTSP source is Amcrest cameras (model # AMNV20M8-4B-B).

I'm using the following startup script to trigger the stream.

#!/bin/bash

AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=rtsp://$3 short-header=TRUE ! rtph264depay ! video/x-h264, format=avc,alignment=au ! kvssink stream-name=$4 storage-size=512

There are 2 issues. It tries to receive UDP packets for 5 seconds and then switches to TCP. On my Mac, I have switched off firewall to ensure that's not a problem.

After it switches to TCP it gives warnings about could not transform video/x-h264 and eventually fails with internal data stream error.

Below are the logs after the pipeline starts playing.

Progress: (open) Retrieving server options

Progress: (open) Retrieving media info

Progress: (request) SETUP stream 0

Progress: (open) Opened Stream

Setting pipeline to PLAYING ...

0:00:00.373601700   267      0x1baaef0 WARN                     bin gstbin.c:2772:gst_bin_do_latency_func:<pipeline0> did not really configure latency of 0:00:00.000000000

New clock: GstSystemClock

Progress: (request) Sending PLAY request

Progress: (request) Sending PLAY request

0:00:00.375093800   267 0x7f416803e450 FIXME                default gstutils.c:3902: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:05.572830600   267      0x1bab450 WARN                 rtspsrc gstrtspsrc.c:4936:gst_rtspsrc_reconnect:<rtspsrc0> warning: Could not receive any UDP packets for 5.0000 seconds, maybe your firewall is blocking it. Retrying using a tcp connection.

WARNING: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Could not read from resource.

Additional debug info:

gstrtspsrc.c(4936): gst_rtspsrc_reconnect (): /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0:
Could not receive any UDP packets for 5.0000 seconds, maybe your firewall is blocking it. Retrying using a tcp connection.

0:00:08.287093000   267 0x7f416803cb70 WARN           basetransform gstbasetransform.c:1346:gst_base_transform_setcaps:<capsfilter0> transform could not transform video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)01640028ffe1000d27640028ac1ad00f0044bca80001000628ee0462c000, level=(string)4, profile=(string)high in anything we support

0:00:08.288605800   267 0x7f416803cb70 WARN           basetransform gstbasetransform.c:1346:gst_base_transform_setcaps:<capsfilter0> transform could not transform video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)01640028ffe1000d27640028ac1ad00f0044bca80001000628ee0462c000, level=(string)4, profile=(string)high in anything we support

0:00:08.288699500   267 0x7f416803cb70 WARN           basetransform gstbasetransform.c:1346:gst_base_transform_setcaps:<capsfilter0> transform could not transform video/x-h264, stream-format=(string)avc, alignment=(string)au, codec_data=(buffer)01640028ffe1000d27640028ac1ad00f0044bca80001000628ee0462c000, level=(string)4, profile=(string)high in anything we support

0:00:08.388455700   267      0x1bab450 WARN                 rtspsrc gstrtspsrc.c:5162:gst_rtspsrc_loop:<rtspsrc0> error: Internal data stream error.

0:00:08.388699000   267      0x1bab450 WARN                 rtspsrc gstrtspsrc.c:5162:gst_rtspsrc_loop:<rtspsrc0> error: streaming stopped, reason not-negotiated (-4)

ERROR: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Internal data stream error.

Additional debug info:

gstrtspsrc.c(5162): gst_rtspsrc_loop (): /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0:
streaming stopped, reason not-negotiated (-4)

Execution ended after 0:00:08.015984100

Setting pipeline to PAUSED ...

Setting pipeline to READY ...

Setting pipeline to NULL ...

0:00:08.391575500   267      0x1bab450 WARN                 rtspsrc gstrtspsrc.c:5466:gst_rtspsrc_try_send:<rtspsrc0> receive interrupted

0:00:08.391630000   267      0x1bab450 WARN                 rtspsrc gstrtspsrc.c:6974:gst_rtspsrc_close:<rtspsrc0> TEARDOWN interrupted

Freeing pipeline ...

INFO - Freeing Kinesis Video Stream rtspdockertest

2019-03-13 17:34:51 [139919806072640] INFO -
freeKinesisVideoStream(): Freeing Kinesis Video stream.

2019-03-13 17:34:51 [139919806072640] DEBUG - streamClosedHandler invoked for upload handle: 18446744073709551615

[msjoshi]

Update:

I tried a public RTSP url and it does not work either.

rtsp://wowzaec2demo.streamlock.net/vod/mp4:BigBuckBunny_115k.mov

[igoticecream]

Came here looking for a solution for the same issue

[chehefen]

Hi, can you add GST_DEBUG=4 to the pipeline like such:

GST_DEBUG=4 AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=rtsp://$3 short-header=TRUE ! rtph264depay ! video/x-h264, format=avc,alignment=au ! kvssink stream-name=$4 storage-size=512

Then send us the log?
Thanks

[msjoshi]

@chehefen

Please find the attached logs with debug level 4.

stream.log

[chehefen]

instead of format=avc, can you try stream-format=avc? You can actually remove the entire video/x-h264, format=avc,alignment=au section as it has already been coded into the kvssink.

[msjoshi]

@chehefen

No difference if I changed format=avc to stream-format=avc.

However, if I remove the entire video/x-h264 from the pipeline, it does not give a transform error like before but fails with internal data stream error, reason not negotiated (-4). I have attached those logs below.

stream.log

[chehefen]

can you try this pipeline?

AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=rtsp://$3 ! rtph264depay ! h264parse ! kvssink stream-name=$4 storage-size=512

[msjoshi]

@chehefen

Adding h264parse in pipeline worked. Thanks!

[msjoshi]

@chehefen

After some more testing, I found one more issue. After about 4 minutes viewing the live camera I get an error FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS. Below is the log snippet. Could this be related to #185

2019-03-19 14:35:27 [139997058459392] DEBUG - fragmentAckReceivedHandler invoked
2019-03-19 14:35:27 [139997058459392] DEBUG - Curl post body write function for stream: rtspdockertest and upload handle: 0 returned: {"EventType":"ERROR","FragmentTimecode":238526,"FragmentNumber":"91343852333181442850799514501683680165321662322","ErrorCode":"FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS","ErrorId":4004}

2019-03-19 14:35:27 [139997058459392] DEBUG - describeStreamHandler invoked
2019-03-19 14:35:27 [139997058459392] DEBUG - streamErrorHandler invoked
2019-03-19 14:35:27 [139997058459392] ERROR - Reporting stream error. Errored timecode: 176130000 Status: 0x52000060
2019-03-19 14:35:27 [139997058459392] DEBUG - fragmentAckReceivedHandler invoked
2019-03-19 14:35:27 [139997058459392] DEBUG - Refreshing credentials. Force refreshing: 0 Now time is: 1553006127454698500 Expiration: 0
2019-03-19 14:35:27 [139997066852096] INFO - Closing connection for upload stream handle: 0
2019-03-19 14:35:27 [139997058459392] DEBUG - Wrote 0 bytes to Kinesis Video. Upload stream handle: 0
2019-03-19 14:35:27 [139997058459392] DEBUG - terminate curl for handle 0
2019-03-19 14:35:27 [139997058459392] DEBUG - Connection for Kinesis Video stream: rtspdockertest closed.
2019-03-19 14:35:27 [139997058459392] DEBUG - Network thread for Kinesis Video stream: rtspdockertest with upload handle: 0 exited. http status: 200
0:04:04.606060600    65 0x7f539c048d90 WARN                 kvssink gstkvssink.cpp:1095:gst_kvs_sink_handle_buffer:<kvssink0> error: Stream error occurred. Status: 0x52000060
0:04:04.606152300    65 0x7f539c048d90 INFO        GST_ERROR_SYSTEM gstelement.c:1938:gst_element_message_full_with_details:<kvssink0> posting message: GStreamer encountered a general stream error.
0:04:04.606210700    65 0x7f539c048d90 INFO        GST_ERROR_SYSTEM gstelement.c:1965:gst_element_message_full_with_details:<kvssink0> posted error message: GStreamer encountered a general stream error.
0:04:04.606289100    65 0x7f539c048d90 INFO                    task gsttask.c:319:gst_task_func:<rtpjitterbuffer0:src> Task going to paused
ERROR: from element /GstPipeline:pipeline0/GstKvsSink:kvssink0: GStreamer encountered a general stream error.
Additional debug info:
/opt/amazon-kinesis-video-streams-producer-sdk-cpp/kinesis-video-gstreamer-plugin/plugin-src/gstkvssink.cpp(1095): gst_kvs_sink_handle_buffer (): /GstPipeline:pipeline0/GstKvsSink:kvssink0:
Stream error occurred. Status: 0x52000060
2019-03-19 14:35:27 [139997058459392] Execution ended after 0:04:04.314214100
Setting pipeline to PAUSED ...

[msjoshi]

@chehefen

Please find the attached logs with DEBUG_DUMP_FRAME_INFO=true. Please note this time the error occurred after 48 minutes of live video and the logs are about 21MB.

stream.log

[MushMal]

@msjoshi looking at the logs I see the following:

• Most of the streaming is going on OK with very little in the buffer
• There are bursts of frame rates hundreds of frames per second - this is very odd.
• Initial stream is in tens of Mbps but it stabilizes at around 6-7Mbps

Closer to the end the following error is returned from the backend.
2019-03-19 15:45:04 [140333919778560] DEBUG - Curl post body write function for stream: rtspdockertest and upload handle: 1 returned: {"EventType":"ERROR","FragmentTimecode":524611,"FragmentNumber":"91343852333181458364664086826070406453078970563","ErrorCode":"FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS","ErrorId":4004}

I am still not sure yet why the media pipeline issues a frame timecode that's less. There is very little in the GST logs. Needs more investigation.

[chehefen]

The issue is that the frame rate is not stable, can you try adding frame rate setting in the capsfilter like this

AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=rtsp://$3 ! rtph264depay ! h264parse ! video/x-h264,framerate=30/1 ! kvssink stream-name=$4 storage-size=512

Also, check your camera settings to make sure there is nothing making the frame rate unstable.

[msjoshi]

@chehefen

Adding the frame rate in caps filter did not work. It fails instantly. See the logs below.

Setting pipeline to PLAYING ...
0:00:01.073514400   236      0x1ab1900 WARN                     bin gstbin.c:2772:gst_bin_do_latency_func:<pipeline0> did not really configure latency of 0:00:00.000000000
New clock: GstSystemClock
Progress: (request) Sending PLAY request
Progress: (request) Sending PLAY request
0:00:01.076400100   236 0x7f4b88048450 FIXME                default gstutils.c:3902: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:06.264090500   236      0x1a6f1e0 WARN                 rtspsrc gstrtspsrc.c:4936:gst_rtspsrc_reconnect:<rtspsrc0> warning: Could not receive any UDP packets for 5.0000 seconds, maybe your firewall is blocking it. Retrying using a tcp connection.
WARNING: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Could not read from resource.
Additional debug info:
gstrtspsrc.c(4936): gst_rtspsrc_reconnect (): /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0:
Could not receive any UDP packets for 5.0000 seconds, maybe your firewall is blocking it. Retrying using a tcp connection.
0:00:08.386078100   236      0x1a6f1e0 WARN                 rtspsrc gstrtspsrc.c:5162:gst_rtspsrc_loop:<rtspsrc0> error: Internal data stream error.
0:00:08.386147500   236      0x1a6f1e0 WARN                 rtspsrc gstrtspsrc.c:5162:gst_rtspsrc_loop:<rtspsrc0> error: streaming stopped, reason not-linked (-1)
ERROR: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Internal data stream error.
Additional debug info:
gstrtspsrc.c(5162): gst_rtspsrc_loop (): /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0:
streaming stopped, reason not-linked (-1)
Execution ended after 0:00:07.312176900
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
0:00:08.387111200   236      0x1a6f1e0 WARN                 rtspsrc gstrtspsrc.c:5466:gst_rtspsrc_try_send:<rtspsrc0> receive interrupted
0:00:08.387155500   236      0x1a6f1e0 WARN                 rtspsrc gstrtspsrc.c:7519:gst_rtspsrc_pause:<rtspsrc0> PAUSE interrupted
Freeing pipeline ...
INFO - Freeing Kinesis Video Stream rtspdockertest
2019-03-21 18:18:21 [139963131811648] INFO -
freeKinesisVideoStream(): Freeing Kinesis Video stream.
2019-03-21 18:18:21 [139963131811648] DEBUG - streamClosedHandler invoked for upload handle: 18446744073709551615

[MushMal]

Looks more like a network issue

[msjoshi]

@MushMal

The below works without frame rate caps filter. Randomly, I get the FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS error.

GST_DEBUG=3 GST_DEBUG_NO_COLOR=1 AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-n=rtsp://user:[email protected]:554 short-header=TRUE ! rtph264depay ! h264parse ! kvssink stream-name=rtspdockertest storage-size=512

[msjoshi]

@unicornss I see a successful streaming label has been added to this issue but that is not the case. This issue is still pending.

My latest log shows the result when using fpsdisplaysink where it shows the correct frame rate. However, when I use kvssink the frame rate is too high and randomly causes dropped frame failure and streaming ends.

[unicornss]

Hi @msjoshi

Sorry for the incorrect label; removed it now.
Are you still seeing same stream error "FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS" after eight minutes?

From previous log:

2019-03-19 14:57:07 [140333928171264] DEBUG - Curl post body write function for stream:"BUFFERING","FragmentTimecode":0,"FragmentNumber":"91343852333181447247962534043354765710711107616"}
:
:
2019-03-19 15:45:04 [140333928171264] DEBUG - Curl post body write function for stream:"RECEIVED","FragmentTimecode":522616,"FragmentNumber":"91343852333181458359712326668928884772144606955"}

2019-03-19 15:45:04 [140333919778560] DEBUG - Curl post body write function for stream:"ERROR","FragmentTimecode":524611,"FragmentNumber":"91343852333181458364664086826070406453078970563","ErrorCode":"FRAGMENT_TIMECODE_LESSER_THAN_PREVIOUS","ErrorId"

[chehefen]

Hi @msjoshi ,

If you dont mind, can you add add_definitions(-DKVS_DEBUG_DUMP_DATA_FILE) at https://github.com/awslabs/amazon-kinesis-video-streams-producer-sdk-cpp/blob/master/kinesis-video-native-build/CMakeLists.txt#L95. Then rebuild the the plugin and stream until the error happens. That line will cause a couple mkv files to be dumped out. If you can send that mkv to us via [email protected], it will help us analyze how to fix the issue.

Thanks

[msjoshi]

@chehefen

I emailed the mkv file as requested.

[msjoshi]

@chehefen

I sent the mkv file as requested couple weeks ago. Any update?

[chehefen]

can you try this pipeline?

GST_PLUGIN_PATH=$PWD AWS_ACCESS_KEY_ID=$1 AWS_SECRET_ACCESS_KEY=$2 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=rtsp://$3 ! rtpjitterbuffer mode=none ! rtph264depay ! h264parse ! kvssink stream-name=$4 storage-size=512

Try to play with rtpjitterbuffer's mode. it can be either none, slave, buffer or synced.

[MushMal]

@msjoshi any update on this issue?

[msjoshi]

@chehefen @MushMal

I'll try it soon and update here.

[MushMal]

@Raghava248 it seems like the issue you are referring to is not related to the issues highlighted in this topic. Do you mind posting this to a new issue? From the error it seems that you are missing h264parse element. Can you describe whether you are using install script and if it succeeds building all the open source dependencies including GStreamer plugins?

[msjoshi]

@Raghava248

This issue is un-related to the issue you are seeing. Please open a separate issue. By mixing multiple issues we lose track of the original issue.

[msjoshi]

@MushMal @chehefen

I tried different modes in rtpjitterbuffer and did not see any difference in frame rates. When I tried fpsdisplaysink earlier the frame rates are shown correctly. Check my post from April 2.

I'm trying to understand why there is such a large difference between KVS metrics for frame rate and fpsdisplaysink.

I must also mention that ever since I set the protocol in rtspsrc to TCP only, the errors and streaming failure went away. Below is the command I'm using in my start streaming script.

#!/bin/bash
GST_DEBUG=$1 AWS_ACCESS_KEY_ID=$2 AWS_SECRET_ACCESS_KEY=$3 AWS_DEFAULT_REGION="us-east-1" gst-launch-1.0 rtspsrc location=$4 short-header=TRUE protocols=GST_RTSP_LOWER_TRANS_TCP ! rtph264depay ! video/x-h264,framerate=25/1 ! h264parse ! kvssink stream-name=$5 storage-size=512

Notice rtspsrc location=$4 short-header=TRUE protocols=GST_RTSP_LOWER_TRANS_TCP.

I'm ready to close this ticket as it has fixed one problem but I do have a latency issue with specific RTSP source. I'll open a new issue so it can be focussed on latency problem.

[MushMal]

@msjoshi while I am not an expert in the rtsp gstreamer plugins, I believe the reason for the observed frame rate is due to "burstiness" of the media pipeline. The KVS core calculates the metrics by adding some "inertia" by deploying EMA (Exponential Mean Averaging) which works really well for steady real-time encoder outputs but is thrown off by bursty sources. I believe that fpsdisplaysink smoothes out the source burstiness and this is the reason why you can see the metrics reflecting the observed FPS.

[MushMal]

Resolving this issue for now. Please create a new one as this thread got too long