Closed daveisfera closed 2 years ago
Anything I can do to help debug this issue?
The docker image you have been using is unfortunately very old and we have not updated the image in a while. You can try building the docker on your own for now using this: https://github.com/aws-samples/amazon-kinesis-video-streams-demos/tree/master/producer-cpp/docker-amazonlinux
I built the image and I'm still seeing an error:
...
[DEBUG] [25-10-2021 20:45:51:157.074 GMT] Dropping frame with flag: 1024
[DEBUG] [25-10-2021 20:45:51:310.471 GMT] postReadCallback(): Wrote 21020 bytes to Kinesis Video. Upload stream handle: 0
[DEBUG] [25-10-2021 20:45:51:310.707 GMT] postWriteCallback(): Curl post body write function for stream with handle: DaveTest and upload handle: 0 returned: {"EventType":"ERROR","FragmentTimecode":1635194731014,"FragmentNumber":"91343852333181590849007091169528640367900605648","ErrorCode":"MAX_FRAGMENT_DURATION_REACHED","ErrorId":4002}
[DEBUG] [25-10-2021 20:45:51:310.743 GMT] streamErrorHandler invoked
[ERROR] [25-10-2021 20:45:51:310.761 GMT] Reported stream error. Errored timecode: 52280000 Status: 0x5200005e
[WARN ] [25-10-2021 20:45:51:310.773 GMT] continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 52280000 Status: 0x5200005e
[DEBUG] [25-10-2021 20:45:51:310.787 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
[DEBUG] [25-10-2021 20:45:51:310.800 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000001
[DEBUG] [25-10-2021 20:45:51:310.814 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
[DEBUG] [25-10-2021 20:45:51:310.945 GMT] fragmentAckReceivedHandler invoked
[WARN ] [25-10-2021 20:45:51:310.970 GMT] getStreamData(): Indicating an end-of-stream for a terminated stream upload handle 0
[INFO ] [25-10-2021 20:45:51:310.987 GMT] postReadCallback(): Reported end-of-stream for stream DaveTest. Upload handle: 0
[DEBUG] [25-10-2021 20:45:51:310.995 GMT] postReadCallback(): Wrote 0 bytes to Kinesis Video. Upload stream handle: 0
[DEBUG] [25-10-2021 20:45:51:311.145 GMT] putStreamCurlHandler(): Network thread for Kinesis Video stream: DaveTest with upload handle: 0 exited. http status: 200
[INFO ] [25-10-2021 20:45:51:670.115 GMT] writeHeaderCallback(): RequestId: f661e397-d230-40d9-99eb-a56cbf0653b5
[DEBUG] [25-10-2021 20:45:51:670.191 GMT] describeStreamCurlHandler(): DescribeStream API response: {"StreamInfo":{"CreationTime":1.63485781205E9,"DataRetentionInHours":2,"DeviceName":"Kinesis_Video_Device","IngestionConfiguration":null,"KmsKeyId":"arn:aws:kms:us-east-1:<id>:alias/aws/kinesisvideo","MediaType":"video/h264","Status":"ACTIVE","StreamARN":"arn:aws:kinesisvideo:us-east-1:<id>:stream/<name>/<number>","StreamName":"DaveTest","Version":"D5nZhjYZciFuvi3TPYR8"}}
[INFO ] [25-10-2021 20:45:51:671.351 GMT] describeStreamResultEvent(): Describe stream result event.
[WARN ] [25-10-2021 20:45:51:671.377 GMT] describeStreamResult(): Content type returned from the DescribeStream call doesn't match the one specified in the StreamInfo
[DEBUG] [25-10-2021 20:45:51:671.395 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000020
[INFO ] [25-10-2021 20:45:52:029.049 GMT] writeHeaderCallback(): RequestId: b02fa23e-b9b9-4981-aee4-ce248f346e21
And then here's the output after I close it:
[DEBUG] [25-10-2021 20:45:52:029.449 GMT] getStreamingEndpointCurlHandler(): GetStreamingEndpoint API response: {"DataEndpoint":"https://<id>.kinesisvideo.us-east-1.amazonaws.com"}
[INFO ] [25-10-2021 20:45:52:030.950 GMT] getStreamingEndpointResultEvent(): Get streaming endpoint result event.
[DEBUG] [25-10-2021 20:45:52:030.990 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
[DEBUG] [25-10-2021 20:45:52:031.024 GMT] getStreamingTokenHandler invoked
[DEBUG] [25-10-2021 20:45:52:031.113 GMT] Refreshing credentials. Force refreshing: 1 Now time is: 1635194752031101300 Expiration: 18446744073709551615
[INFO ] [25-10-2021 20:45:52:031.134 GMT] getStreamingTokenResultEvent(): Get streaming token result event.
[DEBUG] [25-10-2021 20:45:52:031.163 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
[DEBUG] [25-10-2021 20:45:52:031.176 GMT] streamReadyHandler invoked
[DEBUG] [25-10-2021 20:45:52:031.199 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
[INFO ] [25-10-2021 20:45:52:031.405 GMT] putStreamResultEvent(): Put stream result event. New upload handle 1
[WARN ] [25-10-2021 20:45:52:041.634 GMT] notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x7fd424062760
[DEBUG] [25-10-2021 20:45:52:041.667 GMT] stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
[INFO ] [25-10-2021 20:45:52:440.154 GMT] writeHeaderCallback(): RequestId: df3791c9-736a-4399-86c6-88090456f636
[DEBUG] [25-10-2021 20:45:53:061.258 GMT] postReadCallback(): Pausing CURL read for upload handle: 1
[DEBUG] [25-10-2021 20:45:53:180.729 GMT] Dropping frame with flag: 1024
[DEBUG] [25-10-2021 20:45:55:181.722 GMT] Dropping frame with flag: 1024
[DEBUG] [25-10-2021 20:45:57:164.398 GMT] Dropping frame with flag: 1024
[DEBUG] [25-10-2021 20:45:59:178.923 GMT] Dropping frame with flag: 1024
[DEBUG] [25-10-2021 20:46:01:179.534 GMT] Dropping frame with flag: 1024
handling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:36.922729200
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...
[INFO ] [25-10-2021 20:46:02:611.819 GMT] Freeing Kinesis Video Stream DaveTest
[INFO ] [25-10-2021 20:46:02:611.881 GMT] freeKinesisVideoStream(): Freeing Kinesis Video stream.
[DEBUG] [25-10-2021 20:46:02:611.896 GMT] curlApiCallbacksShutdownActiveRequests(): pActiveRequests hashtable is empty
[INFO ] [25-10-2021 20:46:03:115.211 GMT] freeKinesisVideoClient(): Freeing Kinesis Video Client
[DEBUG] [25-10-2021 20:46:03:115.234 GMT] curlApiCallbacksShutdownActiveRequests(): pActiveRequests hashtable is empty
[DEBUG] [25-10-2021 20:46:03:520.573 GMT] freeKinesisVideoClientInternal(): Total allocated memory 0
[WARN ] [25-10-2021 20:46:03:520.622 GMT] curlApiCallbacksShutdown(): curlApiCallbacksShutdown called when already in progress of shutting down
What can I do to figure out what's not working?
On a semi-related note, I noticed that two versions of gstreamer are being installed, but only 1.0 is being used, so #776 fixes that
There seems to be an issue with your source. I see this message in the logs:
WARNING: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Could not read from resource..
Are you sure your source is sending out frames? Can you test this with another sink like filesink? This will help pinpoint if it is a KVS issue or an issue with your pipeline
That same log happens when using a H.264 stream with kvssink and I can view the stream in VLC with both H.264 and H.265.
I tried replacing kvssink
with filesink
and it wrote a file but I couldn't open it with VLC or Quicktime, so how can I test that?
Played with it a bit and realized that I had to add matroskamux
to the pipeline so the video would be encoded and now it's working. So I have been able to have filesink
work with both H.264 and H.265.
And here's the output that was the same in both cases (other than the duration that it prints at the end):
Setting pipeline to PAUSED ...
Pipeline is live and does not need PREROLL ...
Progress: (open) Opening Stream
Progress: (connect) Connecting to rtsp://admin:<password>@192.168.5.53
Progress: (open) Retrieving server options
Progress: (open) Retrieving media info
Progress: (request) SETUP stream 0
Progress: (open) Opened Stream
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Progress: (request) Sending PLAY request
Progress: (request) Sending PLAY request
Progress: (request) Sent PLAY request
WARNING: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Could not read from resource.
Additional debug info:
gstrtspsrc.c(4904): 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.
^Chandling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:25.759780000
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...
When you say it is working, do you mean you see streaming? Does it stream with kvssink?
If not, can you attach debug logs of the SDK alone (without GST_DEBUG=
No, it's still not working with kvssink
when using H.265. filesink
works with both H.264 and H.265, but kvssink
only works with H.264 and is still running into the same problem with H.265.
Here's the output when running kvssink
with the same H.265 stream that works with filesink
:
log4cplus:ERROR could not open file ./kvs_log_configuration
Setting pipeline to PAUSED ...
INFO - createKinesisVideoClient(): Creating Kinesis Video Client
2021-10-29 19:17:16 [140713391449920] INFO - heapInitialize(): Initializing native heap with limit size 536870912, spill ratio 0% and flags 0x00000001
2021-10-29 19:17:16 [140713391449920] INFO - heapInitialize(): Creating AIV heap.
2021-10-29 19:17:16 [140713391449920] INFO - heapInitialize(): Heap is initialized OK
2021-10-29 19:17:16 [140713391449920] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
2021-10-29 19:17:16 [140713391449920] DEBUG - getSecurityTokenHandler invoked
2021-10-29 19:17:16 [140713391449920] DEBUG - Refreshing credentials. Force refreshing: 0 Now time is: 1635535036479816200 Expiration: 0
2021-10-29 19:17:16 [140713391449920] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000010
2021-10-29 19:17:16 [140713391449920] INFO - createDeviceResultEvent(): Create device result event.
2021-10-29 19:17:16 [140713391449920] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
2021-10-29 19:17:16 [140713391449920] DEBUG - clientReadyHandler invoked
2021-10-29 19:17:16 [140713391449920] INFO - try creating stream
2021-10-29 19:17:16 [140713391449920] INFO - Creating Kinesis Video Stream DaveTest
2021-10-29 19:17:16 [140713391449920] INFO - createKinesisVideoStream(): Creating Kinesis Video Stream.
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Kinesis Video Stream Info
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Stream name: DaveTest
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Streaming type: STREAMING_TYPE_REALTIME
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Content type: video/h265
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Max latency (100ns): 600000000
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Fragment duration (100ns): 20000000
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Key frame fragmentation: Yes
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Use frame timecode: Yes
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Absolute frame timecode: Yes
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Nal adaptation flags: 0
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Average bandwith (bps): 4194304
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Framerate: 25
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Buffer duration (100ns): 1200000000
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Replay duration (100ns): 400000000
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Connection Staleness duration (100ns): 600000000
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Store Pressure Policy: 1
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): View Overflow Policy: 1
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Segment UUID: NULL
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Frame ordering mode: 0
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Track list
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Track id: 1
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Track name: kinesis_video
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Codec id: V_MPEGH/ISO/HEVC
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Track type: TRACK_INFO_TYPE_VIDEO
2021-10-29 19:17:16 [140713391449920] DEBUG - logStreamInfo(): Track cpd: NULL
2021-10-29 19:17:16 [140713391449920] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
2021-10-29 19:17:16 [140713391449920] INFO - writeHeaderCallback(): RequestId: c2f3138b-7825-4422-9188-8f384d5ce8df
2021-10-29 19:17:16 [140712677934848] DEBUG - describeStreamCurlHandler(): DescribeStream API response: {"StreamInfo":{"CreationTime":1.63485781205E9,"DataRetentionInHours":2,"DeviceName":"Kinesis_Video_Device","IngestionConfiguration":null,"KmsKeyId":"arn:aws:kms:us-east-1:286047911707:alias/aws/kinesisvideo","MediaType":"video/h264","Status":"ACTIVE","StreamARN":"arn:aws:kinesisvideo:us-east-1:286047911707:stream/DaveTest/1634857812050","StreamName":"DaveTest","Version":"D5nZhjYZciFuvi3TPYR8"}}
2021-10-29 19:17:16 [140712677934848] INFO - describeStreamResultEvent(): Describe stream result event.
2021-10-29 19:17:16 [140712677934848] WARN - describeStreamResult(): Content type returned from the DescribeStream call doesn't match the one specified in the StreamInfo
2021-10-29 19:17:16 [140712677934848] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000020
2021-10-29 19:17:16 [140712677934848] INFO - writeHeaderCallback(): RequestId: 6a05d782-c537-4060-8599-b66a2cd0bed8
2021-10-29 19:17:17 [140712669542144] DEBUG - getStreamingEndpointCurlHandler(): GetStreamingEndpoint API response: {"DataEndpoint":"https://s-808fdb44.kinesisvideo.us-east-1.amazonaws.com"}
2021-10-29 19:17:17 [140712669542144] INFO - getStreamingEndpointResultEvent(): Get streaming endpoint result event.
2021-10-29 19:17:17 [140712669542144] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
2021-10-29 19:17:17 [140712669542144] DEBUG - getStreamingTokenHandler invoked
2021-10-29 19:17:17 [140712669542144] DEBUG - Refreshing credentials. Force refreshing: 1 Now time is: 1635535037192883800 Expiration: 18446744073709551615
2021-10-29 19:17:17 [140712669542144] INFO - getStreamingTokenResultEvent(): Get streaming token result event.
2021-10-29 19:17:17 [140712669542144] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
2021-10-29 19:17:17 [140712669542144] DEBUG - streamReadyHandler invoked
2021-10-29 19:17:17 [140712669542144] Stream is ready
Pipeline is live and does not need PREROLL ...
Progress: (open) Opening Stream
Progress: (connect) Connecting to rtsp://admin:DavesCamera1@192.168.5.53
Progress: (open) Retrieving server options
Progress: (open) Retrieving media info
Progress: (request) SETUP stream 0
Progress: (open) Opened Stream
Setting pipeline to PLAYING ...
New clock: GstSystemClock
Progress: (request) Sending PLAY request
Progress: (request) Sending PLAY request
Progress: (request) Sent PLAY request
WARNING: from element /GstPipeline:pipeline0/GstRTSPSrc:rtspsrc0: Could not read from resource.
Additional debug info:
gstrtspsrc.c(4904): 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.
INFO - kinesisVideoStreamFormatChanged(): Stream format changed.
2021-10-29 19:17:22 [140712537442048] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
2021-10-29 19:17:22 [140712537442048] INFO - putStreamResultEvent(): Put stream result event. New upload handle 0
2021-10-29 19:17:22 [140712537442048] WARN - notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x7ffa18015fd0
2021-10-29 19:17:22 [140712537442048] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
2021-10-29 19:17:22 [140712537442048] DEBUG - Kinesis Video client and stream metrics
>> Overall storage byte size: 536870912
>> Available storage byte size: 536807230
>> Allocated storage byte size: 63682
>> Total view allocation byte size: 144080
>> Total streams elementary frame rate (fps): 25
>> Total streams transfer rate (bps): 33554432 (32768 Kbps)
>> Current view duration (ms): 0
>> Overall view duration (ms): 0
>> Current view byte size: 63634
>> Overall view byte size: 63634
>> Current elementary frame rate (fps): 25
>> Current transfer rate (bps): 33554432 (32768 Kbps)
2021-10-29 19:17:22 [140712537442048] INFO - writeHeaderCallback(): RequestId: cac72ef5-de72-3f96-9331-65f65f416d50
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 65524 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 8723 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 704 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 2492 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1454 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1554 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1449 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postWriteCallback(): Curl post body write function for stream with handle: DaveTest and upload handle: 0 returned: {"EventType":"BUFFERING","FragmentTimecode":1635535042556,"FragmentNumber":"91343852333181640366608662584830988030961984119"}
2021-10-29 19:17:23 [140712238634752] DEBUG - fragmentAckReceivedHandler invoked
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1194 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1085 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1021 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 3053 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1037 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 650 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 504 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 4360 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1654 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1741 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1512 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 7431 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 145 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 292 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 221 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 410 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 1197 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 755 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 5725 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 175 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:23 [140712238634752] DEBUG - postReadCallback(): Wrote 702 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 621 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 519 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 4530 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 456 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 4206 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 3352 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 2653 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 2828 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 303 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 5049 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 2017 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 2343 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 1928 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:24 [140712537442048] DEBUG - postReadCallback(): Wrote 4284 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 2451 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 709 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 3754 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 1523 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 3176 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 1020 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:24 [140712238634752] DEBUG - postReadCallback(): Wrote 5145 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1957 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 2096 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1818 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1527 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1539 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1612 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 7677 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 206 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 198 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 897 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 6077 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 491 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 559 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 4590 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 631 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 3430 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 3139 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 2397 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 4785 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 2155 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 5160 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1945 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1726 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 4710 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1897 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 1793 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:25 [140712238634752] DEBUG - postReadCallback(): Wrote 5908 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 3601 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 1707 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 6742 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 6544 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 2561 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 2826 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 4935 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 2460 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 2398 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 2408 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 5746 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - postReadCallback(): Wrote 10414 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:26 [140712238634752] DEBUG - Dropping frame with flag: 1024
Then that repeats for a while and eventually this is output:
2021-10-29 19:17:42 [140712238634752] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:42 [140712537442048] DEBUG - postReadCallback(): Wrote 25034 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postReadCallback(): Wrote 2948 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postReadCallback(): Wrote 2631 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postReadCallback(): Wrote 2607 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postReadCallback(): Wrote 2002 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postWriteCallback(): Curl post body write function for stream with handle: DaveTest and upload handle: 0 returned: {"EventType":"ERROR","FragmentTimecode":1635535042556,"FragmentNumber":"91343852333181640366608662584830988030961984119","ErrorCode":"MAX_FRAGMENT_DURATION_REACHED","ErrorId":4002}
2021-10-29 19:17:42 [140712238634752] DEBUG - streamErrorHandler invoked
2021-10-29 19:17:42 [140712238634752] ERROR - Reported stream error. Errored timecode: 51900000 Status: 0x5200005e
2021-10-29 19:17:42 [140712238634752] WARN - continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 51900000 Status: 0x5200005e
2021-10-29 19:17:42 [140712238634752] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
2021-10-29 19:17:42 [140712238634752] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000001
2021-10-29 19:17:42 [140712238634752] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
2021-10-29 19:17:42 [140712238634752] DEBUG - fragmentAckReceivedHandler invoked
2021-10-29 19:17:42 [140712238634752] WARN - getStreamData(): Indicating an end-of-stream for a terminated stream upload handle 0
2021-10-29 19:17:42 [140712238634752] INFO - postReadCallback(): Reported end-of-stream for stream DaveTest. Upload handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - postReadCallback(): Wrote 0 bytes to Kinesis Video. Upload stream handle: 0
2021-10-29 19:17:42 [140712238634752] DEBUG - putStreamCurlHandler(): Network thread for Kinesis Video stream: DaveTest with upload handle: 0 exited. http status: 200
2021-10-29 19:17:42 [140712238634752] INFO - writeHeaderCallback(): RequestId: 87384e11-ebb8-4565-95d2-cdc75eff0f58
2021-10-29 19:17:43 [140712255420160] DEBUG - describeStreamCurlHandler(): DescribeStream API response: {"StreamInfo":{"CreationTime":1.63485781205E9,"DataRetentionInHours":2,"DeviceName":"Kinesis_Video_Device","IngestionConfiguration":null,"KmsKeyId":"arn:aws:kms:us-east-1:286047911707:alias/aws/kinesisvideo","MediaType":"video/h264","Status":"ACTIVE","StreamARN":"arn:aws:kinesisvideo:us-east-1:286047911707:stream/DaveTest/1634857812050","StreamName":"DaveTest","Version":"D5nZhjYZciFuvi3TPYR8"}}
2021-10-29 19:17:43 [140712255420160] INFO - describeStreamResultEvent(): Describe stream result event.
2021-10-29 19:17:43 [140712255420160] WARN - describeStreamResult(): Content type returned from the DescribeStream call doesn't match the one specified in the StreamInfo
2021-10-29 19:17:43 [140712255420160] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000020
2021-10-29 19:17:43 [140712255420160] INFO - writeHeaderCallback(): RequestId: c199473d-441e-4846-ab49-66bd5494fa0a
2021-10-29 19:17:43 [140712569722624] DEBUG - getStreamingEndpointCurlHandler(): GetStreamingEndpoint API response: {"DataEndpoint":"https://s-808fdb44.kinesisvideo.us-east-1.amazonaws.com"}
2021-10-29 19:17:43 [140712569722624] INFO - getStreamingEndpointResultEvent(): Get streaming endpoint result event.
2021-10-29 19:17:43 [140712569722624] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
2021-10-29 19:17:43 [140712569722624] DEBUG - getStreamingTokenHandler invoked
2021-10-29 19:17:43 [140712569722624] DEBUG - Refreshing credentials. Force refreshing: 1 Now time is: 1635535063784282100 Expiration: 18446744073709551615
2021-10-29 19:17:43 [140712569722624] INFO - getStreamingTokenResultEvent(): Get streaming token result event.
2021-10-29 19:17:43 [140712569722624] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
2021-10-29 19:17:43 [140712569722624] DEBUG - streamReadyHandler invoked
2021-10-29 19:17:43 [140712569722624] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
2021-10-29 19:17:43 [140712569722624] INFO - putStreamResultEvent(): Put stream result event. New upload handle 1
2021-10-29 19:17:43 [140712569722624] WARN - notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x7ffa14078e80
Then I hit Ctrl-C to stop it and it outputs the following:
2021-10-29 19:17:43 [140712569722624] DEBUG - stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
2021-10-29 19:17:43 [140712569722624] INFO - writeHeaderCallback(): RequestId: f32e6c37-f01f-0b49-aad8-272f0c79dc87
2021-10-29 19:17:44 [140712255420160] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:44 [140712537442048] DEBUG - postReadCallback(): Pausing CURL read for upload handle: 1
2021-10-29 19:17:44 [140712255420160] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:46 [140712537442048] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:48 [140712537442048] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:50 [140712537442048] DEBUG - Dropping frame with flag: 1024
2021-10-29 19:17:52 [140712537442048] handling interrupt.
Interrupt: Stopping pipeline ...
Execution ended after 0:00:35.480634400
Setting pipeline to PAUSED ...
Setting pipeline to READY ...
Setting pipeline to NULL ...
Freeing pipeline ...
INFO - Freeing Kinesis Video Stream DaveTest
2021-10-29 19:17:52 [140713391449920] INFO - freeKinesisVideoStream(): Freeing Kinesis Video stream.
2021-10-29 19:17:52 [140713391449920] DEBUG - curlApiCallbacksShutdownActiveRequests(): pActiveRequests hashtable is empty
2021-10-29 19:17:52 [140713391449920] INFO - freeKinesisVideoClient(): Freeing Kinesis Video Client
2021-10-29 19:17:53 [140713391449920] DEBUG - curlApiCallbacksShutdownActiveRequests(): pActiveRequests hashtable is empty
2021-10-29 19:17:53 [140713391449920] DEBUG - freeKinesisVideoClientInternal(): Total allocated memory 0
2021-10-29 19:17:54 [140713391449920] WARN - curlApiCallbacksShutdown(): curlApiCallbacksShutdown called when already in progress of shutting down
2021-10-29 19:17:54 [140713391449920] %
My bad I clsoed the issue with a comment. Will investigate the logs and get back. Thank you.
Thanks and let me know if there's anything I can help with.
On a semi-related note, could/should the Dropping frame with flag: 1024
log message be at ERROR
or at least WARN
level?
Anything I can do to help further test/debug the problem?
Is there any sort of bug bounty or such that we could do to help prioritize this getting fixed?
Just looking at the returned error: 0x5200005e - this is defined in https://docs.aws.amazon.com/kinesisvideostreams/latest/dg/producer-sdk-errors.html
0x5200005e | STATUS_ACK_ERR_FRAGMENT_DURATION_REACHED | The maximum fragment duration was reached. | The max fragment duration is defined in Producer SDK Limits. This error indicates that there are either very low frames per second or there are no key frames to create manageable duration fragments. Check the encoder settings and ensure that key frames are being produced properly at the regular intervals. -- | -- | -- | --This is an indicator that your encoder is not producing regular key-frames. I am not familiar with the encoder settings but can you readup a little on it and set it to cut an Idr frame every 2-4 seconds?
Yes, it's generating an I-frame every 2 seconds just like with the H.264 setup. The resolution and frame rate are identical with both the H.264 and H.265 setup. VLC shows the stream and using filesink
records it to a file and then QuickTime can display it, so it appears to be a standard/compliant stream of video and there's something going wrong in the handling of the stream in the kvssink
plugin.
KVS is attempting to have no assumption about the underlying streams - as such, it has a concept of a key-frame and non-key-frame instead of Idr and non-Idr frames. There are areas where things can be encoding specific. Those are in the area of CPD extraction/processing and in the backend, the playback (HLS/DASH/Console playback) but other than that there is no assumption made. In your case, the issue here is to 1) ensure the I-frames are produced at a regular intervals from the encoder and 2) the I-frames are properly interpreted by the KVS sink as key-frames.
If you are sure your source (encoder) produces proper GoPs then the issue must be how kvs sink GStreamer plugin interprets the flags.
Perhaps someone from KVS team can chime whether they have a test based on some H265 (perhaps software) encoder that successfully gets ingested?
Yes, there appears to be a key frame every 2 seconds, because here's the output of checking that on the output of filesink
with ffprobe
:
$ ffprobe -show_frames /tmp/dlj/output.mp4 | grep -i key_frame | uniq -c
Input #0, matroska,webm, from '/tmp/dlj/output.mkv':
Metadata:
encoder : GStreamer matroskamux version 1.10.4
creation_time : 2021-11-11T00:27:47.000000Z
Duration: 00:00:04.84, start: 5.355000, bitrate: 1057 kb/s
Stream #0:0(eng): Video: hevc (Main), yuv420p(tv), 1280x720, SAR 1:1 DAR 16:9, 30 fps, 30 tbr, 1k tbn, 1k tbc (default)
Metadata:
title : Video
1 key_frame=1
59 key_frame=0
1 key_frame=1
59 key_frame=0
1 key_frame=1
25 key_frame=0
You can see that there are 59 frames between each key-frame and the video is at 30 fps, so that should be a key-frame every 2 seconds.
We really want to get this working, so I'm glad to help out with anything I can to figure this out. Also, is there anyone that's worked on the kvssink
code that could be prioritized through a bug bounty or something similar?
If I were to guess the flag value of 1024 is GST_BUFFER_FLAG_HEADER
Do you mind replacing the following line: https://github.com/awslabs/amazon-kinesis-video-streams-producer-sdk-cpp/blob/2b9436dbc7152b2f0374b795c4705e91fa9a5460/src/gstreamer/gstkvssink.cpp
(GST_BUFFER_FLAG_IS_SET(buf, GST_BUFFER_FLAG_HEADER) && (!GST_BUFFER_PTS_IS_VALID(buf) || !GST_BUFFER_DTS_IS_VALID(buf)));
with the following line:
(GST_BUFFER_FLAG_IS_SET(buf, GST_BUFFER_FLAG_HEADER) && (!GST_BUFFER_PTS_IS_VALID(buf) && !GST_BUFFER_DTS_IS_VALID(buf)));
Basically, stating that if the buffer contains a header and no PTS and DTS then skip it
Ok, I got it to work by upgrading the base image to rockylinux/rockylinux:8
or fedora:35
. It appears the fix is from the newer version of gstreamer
that's being used there (i.e. amazonlinux:2
is pretty old now and I wish there was an amazonlinux:3
based on RHEL 8 😢 )
@daveisfera ,
Apologies for not getting back sooner. But glad updating the base image helped. I am resolving this ticket. Feel free to reach out if you face any more issues. Thank you!
Is there a plan to make the official images be something other than amazonlinux:2
? If not, is there a recommended base image?
@daveisfera , There is not a plan to support anything other than amazonlinux:2 at the moment.
Other than amazonlinux, I would look into ubuntu latest image and see how that works out. I have personally not tested it out though for this SDK.
Is support for H.265 going to be removed from the documentation then? This is what's pointed to in the official AWS documentation and it doesn't actually support H.265 so it seems that at least a disclaimer should be added.
Here's the status of images that I tested with:
Fedora 34
: drops with flag 1536 on H.264
Fedora 35
: won't start
Debug buster
: works with H.265
Debian bullseye
: drops with flag 1536 on H.264
Rocky Linux 8
: works with H.265
Debian buster
uses 1.14 and Rocky Linux
uses 1.16, so it appears that something in 1.17 or 1.18 doesn't work with kvssink
Logging
Describe the bug Uploading video that's in H.264 works, but switching the camera and the parsing to H.265 runs into an error.
To Reproduce Steps to reproduce the behavior:
Expected behavior H.265 should work like H.264
SDK version number Current version available in the docker image (how do I check this?)
Open source building Using the docker image at
546150905175.dkr.ecr.us-west-2.amazonaws.com/kinesis-video-producer-sdk-cpp-amazon-linux
Platform (please complete the following information):