fix state machine issue on auth failure force retry auth and reset gr…

[hassanctech]

Issue #, if available:https://github.com/awslabs/amazon-kinesis-video-streams-producer-c/issues/221

Description of changes:

There's a bug where if auth refresh fails and we call putFrame it will try to step the stream state machine from STOPPED to GET ENDPOINT, in this process it will try to step the client state machine from READY to AUTH state in this transition it actually attempts to make the curl call to refresh the creds but due to a boolean that was set it will just return and cause putFrame to commence without error when in fact we don't have creds.

By submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.

[codecov-commenter]

Codecov Report

Merging #125 (a2d9036) into master (9ef93e5) will decrease coverage by 0.07%. The diff coverage is 46.66%.

@@            Coverage Diff             @@
##           master     #125      +/-   ##
==========================================
- Coverage   87.13%   87.05%   -0.08%     
==========================================
  Files          50       50              
  Lines        9107     9119      +12     
==========================================
+ Hits         7935     7939       +4     
- Misses       1172     1180       +8     

Impacted Files	Coverage Δ
src/client/src/StreamState.c	93.77% <28.57%> (-1.64%)	:arrow_down:
src/client/src/Stream.c	83.78% <33.33%> (-0.13%)	:arrow_down:
src/client/src/AuthIntegration.c	95.31% <66.66%> (-1.41%)	:arrow_down:
src/client/src/StreamEvent.c	90.05% <100.00%> (+0.02%)	:arrow_up:

---

Continue to review full report at Codecov.

Legend - Click here to learn more Δ = absolute <relative> (impact), ø = not affected, ? = missing data Powered by Codecov. Last update 9ef93e5...a2d9036. Read the comment docs.

[MushMal]

Oh, and one more thing... This is easily automated so can be nicely unit test covered

[MushMal]

Excellent explanation @hassanctech

We do have two issues indeed. 1) Ensuring we don't trip on the set grace period boolean on a failure 2) Ensuring that a higher-level continuous retry state machine can make progress while the lowest-level client state machine has already reached it's max retry count.

I have prepared a PR but for some odd reason I don't have access to upload it.

Attaching the txt file - see if you can apply and see how that works.

P.S. It's empirical to do add a unit test hitting this path and ensuring it actually does what it intended to do. diff.txt

[hassanctech]

Excellent explanation @hassanctech

We do have two issues indeed.

1. Ensuring we don't trip on the set grace period boolean on a failure
2. Ensuring that a higher-level continuous retry state machine can make progress while the lowest-level client state machine has already reached it's max retry count.

I have prepared a PR but for some odd reason I don't have access to upload it.

Attaching the txt file - see if you can apply and see how that works.

P.S. It's empirical to do add a unit test hitting this path and ensuring it actually does what it intended to do. diff.txt

To create a PR you have to create a fork and then a branch on that fork.

I had a look at the diff, I have two concerns:

1. I avoided putting anything in stepClientStateMachine because currently the code is not consistent to only use this function to step the client state machine, in some places in the code we actually step it by calling stepStateMachine directly , for example: https://github.com/awslabs/amazon-kinesis-video-streams-pic/blob/master/src/client/src/ClientState.c#L168. Perhaps those should all be fixed since they're being done outside the client lock. There's nothing preventing someone from calling that function instead.
2. I do not understand the point of the resetGrace boolean, at least not what I saw in the diff. Maybe I missed something but from what I understand:

   +    if (resetGrace) {
   +        pKinesisVideoStream->gracePeriod = FALSE;
   +    }

Regardless of the result of streamTerminatedEvent you will set gracePeriod to FALSE but this is not what we want right? If the call succeeded then we should wait for on a different thread when getStreamingTokenResult is called which resets the gracePeriod to FALSE. But with your change it will always set it FALSE as long as we got past the initial checks but regardless of the return value of streamTerminatedEvent. Do you see an issue with what I have in the PR? Agreed about the tests I'm working on drafting those.

I do like the idea of having the logic for checking for the AUTH error higher up in the stepClientStateMachine but there are like 8-9 places where we step the client state machine using stepStateMachine so we will miss those cases, I'm not sure if there was a reason for the difference there if not I can fix all of those and move it there.

[schultetwin1]

@hassanctech - I was able to test this fix and unfortunately it did not seem to solve the underlying issue. After putKinesisVideoFrame returned STATUS_IOT_FAILED the SDK stopped uploading frames to the AWS server.

I repro'd without verbose logging turned on so I will attempt to get those logs for you on Monday.

[hassanctech]

@hassanctech - I was able to test this fix and unfortunately it did not seem to solve the underlying issue. After putKinesisVideoFrame returned STATUS_IOT_FAILED the SDK stopped uploading frames to the AWS server.

I repro'd without verbose logging turned on so I will attempt to get those logs for you on Monday.

Ok looking forward to those logs, did you see anything different in the standard logging? Was it exactly the same as before or was there some difference? I'm looking at it again now and will add some testing around it as well.

[MushMal]

Excellent explanation @hassanctech We do have two issues indeed.

1. Ensuring we don't trip on the set grace period boolean on a failure
2. Ensuring that a higher-level continuous retry state machine can make progress while the lowest-level client state machine has already reached it's max retry count.

I have prepared a PR but for some odd reason I don't have access to upload it. Attaching the txt file - see if you can apply and see how that works. P.S. It's empirical to do add a unit test hitting this path and ensuring it actually does what it intended to do. diff.txt

To create a PR you have to create a fork and then a branch on that fork.

I had a look at the diff, I have two concerns:

1. I avoided putting anything in stepClientStateMachine because currently the code is not consistent to only use this function to step the client state machine, in some places in the code we actually step it by calling stepStateMachine directly , for example: https://github.com/awslabs/amazon-kinesis-video-streams-pic/blob/master/src/client/src/ClientState.c#L168. Perhaps those should all be fixed since they're being done outside the client lock. There's nothing preventing someone from calling that function instead.
2. I do not understand the point of the resetGrace boolean, at least not what I saw in the diff. Maybe I missed something but from what I understand:

+    if (resetGrace) {
+        pKinesisVideoStream->gracePeriod = FALSE;
+    }

Regardless of the result of streamTerminatedEvent you will set gracePeriod to FALSE but this is not what we want right? If the call succeeded then we should wait for on a different thread when getStreamingTokenResult is called which resets the gracePeriod to FALSE. But with your change it will always set it FALSE as long as we got past the initial checks but regardless of the return value of streamTerminatedEvent. Do you see an issue with what I have in the PR? Agreed about the tests I'm working on drafting those.

I do like the idea of having the logic for checking for the AUTH error higher up in the stepClientStateMachine but there are like 8-9 places where we step the client state machine using stepStateMachine so we will miss those cases, I'm not sure if there was a reason for the difference there if not I can fix all of those and move it there.

1) the stepClientStateMachine should be used from the external source. Within the state machine itself it's OK to call step directly. 2) My bad - it should be if (STATUS_FAILED(retStatus) && resetGrace) in the cleanup clause

As I mentioned a test needs to target this case so it's easier to reason

[schultetwin1]

I attempted a repro with more verbose logging. I compile libcproducer.so with the changes in fix-state-machine-issue. Before I could get to the step of "degrade network", I noticed that the KVS SDK seemed to be stuck in some sort of continuous retry loop:

Jun 21 22:59:57 kvs_stream: continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 16243156759800000 Status: 0x52000062
Jun 21 22:59:57 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 0 for stream handle 758
Jun 21 22:59:57 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 9104336. Upload handle 758. Duration available in 100ns: 0. Bytes available: 0
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000001
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
Jun 21 22:59:57 kvs_stream: describeStreamCachingCurl(): No-op DescribeStream API call
Jun 21 22:59:57 kvs_stream: describeStreamResultEvent(): Describe stream result event.
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000020
Jun 21 22:59:57 kvs_stream: getStreamingEndpointCachingCurl(): Caching GetStreamingEndpoint API call
Jun 21 22:59:57 kvs_stream: getStreamingEndpointResultEvent(): Get streaming endpoint result event.
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
Jun 21 22:59:57 kvs_stream: getStreamingTokenResultEvent(): Get streaming token result event.
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
Jun 21 22:59:57 kvs_stream: [kvs_module.c:178]Stream Ready. Stream Handle: 9104336
Jun 21 22:59:57 kvs_stream: ret = 0 0 117
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
Jun 21 22:59:57 kvs_stream: putStreamResultEvent(): Put stream result event. New upload handle 759
Jun 21 22:59:57 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 84 for stream handle 759
Jun 21 22:59:57 kvs_stream: notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x8d08d8
Jun 21 22:59:57 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 9104336. Upload handle 759. Duration available in 100ns: 0. Bytes available: 84
Jun 21 22:59:57 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
Jun 21 22:59:57 kvs_stream: [kvs_module.c:160]Received fragment ack: Seq num  Stream handle 9104336 Status ERROR
Jun 21 22:59:57 kvs_stream: Timestamp: -1 Stream Name: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f
Jun 21 22:59:57 kvs_stream: [kvs_module.c:170]Fragment Ack Error Type: 4006
Jun 21 22:59:57 kvs_stream: postWriteCallback(): Processed ACK OK.
Jun 21 22:59:57 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:57 kvs_stream: getStreamData(): Indicating an end-of-stream for a terminated stream upload handle 758
Jun 21 22:59:57 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 758 current stream handle: 9104336
Jun 21 22:59:57 kvs_stream: postReadCallback(): Reported end-of-stream for stream 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f. Upload handle: 758
Jun 21 22:59:57 kvs_stream: postReadCallback(): Wrote 0 bytes to Kinesis Video. Upload stream handle: 758
Jun 21 22:59:57 kvs_stream: putStreamCurlHandler(): Network thread for Kinesis Video stream: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f with upload handle: 758 exited. http status: 200
Jun 21 22:59:58 kvs_stream: writeHeaderCallback(): RequestId: d1bdc6a7-29ac-c895-88f6-da898c255bad
Jun 21 22:59:58 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 449 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Wrote 449 bytes to Kinesis Video. Upload stream handle: 759
Jun 21 22:59:58 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 iCamera: [DN:892]dbg: www.google.com ==> 142.251.33.100, Success!
Jun 21 22:59:58 iCamera: [netService]dbg: connect server(142.251.33.100:80)  succeed!
Jun 21 22:59:58 iCamera: [metricsserver.c:270]MetricsData recv:: {"metrics_type":"app/kvs_stream_start", "metrics_content":{"handle":9104336}, "metrics_ts":1624316396239}
Jun 21 22:59:58 iCamera: [metricsserver.c:270]MetricsData recv:: {"metrics_type":"app/kvs_stream_start", "metrics_content":{"handle":9104336}, "metrics_ts":1624316397108}
Jun 21 22:59:58 iCamera: [metricsserver.c:270]MetricsData recv:: {"metrics_type":"app/kvs_stream_start", "metrics_content":{"handle":9104336}, "metrics_ts":1624316397970}
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Pausing CURL read for upload handle: 759
Jun 21 22:59:58 kvs_stream: postWriteCallback(): postBodyStreamingWriteFunc (curl callback) invoked
Jun 21 22:59:58 kvs_stream: postWriteCallback(): Curl post body write function for stream with handle: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f and upload handle: 759 returned: {"EventTy}
Jun 21 22:59:58 kvs_stream: 
Jun 21 22:59:58 kvs_stream: continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 16243156759800000 Status: 0x52000062
Jun 21 22:59:58 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 0 for stream handle 759
Jun 21 22:59:58 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 9104336. Upload handle 759. Duration available in 100ns: 0. Bytes available: 0
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000001
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002
Jun 21 22:59:58 kvs_stream: describeStreamCachingCurl(): No-op DescribeStream API call
Jun 21 22:59:58 kvs_stream: describeStreamResultEvent(): Describe stream result event.
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000020
Jun 21 22:59:58 kvs_stream: getStreamingEndpointCachingCurl(): Caching GetStreamingEndpoint API call
Jun 21 22:59:58 kvs_stream: getStreamingEndpointResultEvent(): Get streaming endpoint result event.
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
Jun 21 22:59:58 kvs_stream: getStreamingTokenResultEvent(): Get streaming token result event.
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
Jun 21 22:59:58 kvs_stream: [kvs_module.c:178]Stream Ready. Stream Handle: 9104336
Jun 21 22:59:58 kvs_stream: ret = 0 0 117
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
Jun 21 22:59:58 kvs_stream: putStreamResultEvent(): Put stream result event. New upload handle 760
Jun 21 22:59:58 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 84 for stream handle 760
Jun 21 22:59:58 kvs_stream: notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x8ea670
Jun 21 22:59:58 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 9104336. Upload handle 760. Duration available in 100ns: 0. Bytes available: 84
Jun 21 22:59:58 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
Jun 21 22:59:58 kvs_stream: [kvs_module.c:160]Received fragment ack: Seq num  Stream handle 9104336 Status ERROR
Jun 21 22:59:58 kvs_stream: Timestamp: -1 Stream Name: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f
Jun 21 22:59:58 kvs_stream: [kvs_module.c:170]Fragment Ack Error Type: 4006
Jun 21 22:59:58 kvs_stream: postWriteCallback(): Processed ACK OK.
Jun 21 22:59:58 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:58 kvs_stream: getStreamData(): Indicating an end-of-stream for a terminated stream upload handle 759
Jun 21 22:59:58 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 759 current stream handle: 9104336
Jun 21 22:59:58 kvs_stream: postReadCallback(): Reported end-of-stream for stream 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f. Upload handle: 759
Jun 21 22:59:58 kvs_stream: postReadCallback(): Wrote 0 bytes to Kinesis Video. Upload stream handle: 759
Jun 21 22:59:58 kvs_stream: putStreamCurlHandler(): Network thread for Kinesis Video stream: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f with upload handle: 759 exited. http status: 200
Jun 21 22:59:59 kvs_stream: writeHeaderCallback(): RequestId: c3ae2643-3062-6a94-9ae5-3a6c9e5e7a4c
Jun 21 22:59:59 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 449 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Wrote 449 bytes to Kinesis Video. Upload stream handle: 760
Jun 21 22:59:59 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 760 current stream handle: 9104336
Jun 21 22:59:59 kvs_stream: postReadCallback(): Pausing CURL read for upload handle: 760
Jun 21 22:59:59 kvs_stream: postWriteCallback(): postBodyStreamingWriteFunc (curl callback) invoked
Jun 21 22:59:59 kvs_stream: postWriteCallback(): Curl post body write function for stream with handle: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f and upload handle: 760 returned: {"EventTy}
Jun 21 22:59:59 kvs_stream: 
Jun 21 22:59:59 kvs_stream: continuousRetryStreamErrorReportHandler(): Reporting stream error. Errored timecode: 16243156759800000 Status: 0x52000062
Jun 21 22:59:59 kvs_stream: [kvs_module.c:259][count:5]Reported streamError callback for stream handle 9104336. Upload handle 760. Fragment timecode in 100ns: 16243156759800000. Error status: 0x52000062
Jun 21 22:59:59 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 0 for stream handle 760
Jun 21 22:59:59 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 9104336. Upload handle 760. Duration available in 100ns: 0. Bytes available: 0
Jun 21 22:59:59 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
Jun 21 22:59:59 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000001
Jun 21 22:59:59 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000001, Next state: 0x0000000000000002

These log messages keep being printed out over and over. This maybe a separate issue but I wanted to post it here in case it was related to the solution.

I am still working on getting the logs of a repro with this change.

[MushMal]

@schultetwin1 in this case the SDK generates an invalid MKV (0x52000062)

https://docs.aws.amazon.com/kinesisvideostreams/latest/dg/producer-sdk-errors.html

A higher-level continuous retry then retries sending the bits which seem to be "bad" which then generates the same error. In the later versions/commits, there were numerous fixes that would minimize/avoid generating invalid MKV (on pressure sending a partial frame, etc) and even if it does end up with the invalid fragment then that fragment would be skipped. Try to update to the latest commit/

[schultetwin1]

Gotcha, thanks for the info! Let's assume that's a different error for now.

Try to update to the latest commit.

This error was not reproducible, so I'm not too worried about it. I'm going to stick with testing against your latest release as that is what we release to our customers.

[hassanctech]

Gotcha, thanks for the info! Let's assume that's a different error for now.

Try to update to the latest commit.

This error was not reproducible, so I'm not too worried about it. I'm going to stick with testing against your latest release as that is what we release to our customers.

OK, I'll wait for your logs with the repro (I shared earlier the parameter you can modify to repro more quickly within a few minutes). Once I have those I can examine and see what may be happening.

[schultetwin1]

Hi @hassanctech, here are the logs.

Jun 24 23:32:17 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 90000 bytes 4306 for stream handle 3
Jun 24 23:32:17 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 90000. Bytes available: 4306
Jun 24 23:32:17 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 480000 bytes 4639 for stream handle 3
Jun 24 23:32:17 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 480000. Bytes available: 4639
Jun 24 23:32:17 kvs_stream: [streamrcv.c:264][KVS] Put 940 frames.
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 4639 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: postReadCallback(): Wrote 4639 bytes to Kinesis Video. Upload stream handle: 3
Jun 24 23:32:17 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245775378989840, dts: 16245775378989840, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:32:17 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 3221 for stream handle 3
Jun 24 23:32:17 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 0. Bytes available: 3221
Jun 24 23:32:17 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245775379281820, dts: 16245775379281820, duration: 0, size: 3789, trackId: 1, isKey 0
Jun 24 23:32:17 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 370000 bytes 3554 for stream handle 3
Jun 24 23:32:17 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 370000. Bytes available: 3554
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 3554 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: postReadCallback(): Wrote 3554 bytes to Kinesis Video. Upload stream handle: 3
Jun 24 23:32:17 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245775379318800, dts: 16245775379318800, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:32:17 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 3802 for stream handle 3
Jun 24 23:32:17 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 0. Bytes available: 3802
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 3802 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: postReadCallback(): Wrote 3802 bytes to Kinesis Video. Upload stream handle: 3
Jun 24 23:32:17 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:17 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245775379718550, dts: 16245775379718550, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:32:17 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:18 kvs_stream: [streamrcv.c:270][KVS] Put 944 frames.
Jun 24 23:32:18 kvs_stream: [kvs_module.c:761][kvs info]
Jun 24 23:32:18 kvs_stream: [kvs_module.c:762]Duration from the current to the head in 100ns:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:763]Overall duration from the tail to the head in 100ns:15730000
Jun 24 23:32:18 kvs_stream: [kvs_module.c:764]Size from the current to the head in bytes:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:765]Overall size from the tail to the head in bytes:174631
Jun 24 23:32:18 kvs_stream: [kvs_module.c:766]Last measured put frame rate in bytes per second:16.507823
Jun 24 23:32:18 kvs_stream: [kvs_module.c:767]Last measured transfer rate in bytes per second:103942
Jun 24 23:32:18 kvs_stream: [kvs_module.c:768]Total stream duration - stream uptime:13481028103
Jun 24 23:32:18 kvs_stream: [kvs_module.c:769]Total transferred bytes:11013873
Jun 24 23:32:18 kvs_stream: [kvs_module.c:770]Total number of streaming sessions including new/errored/active:4
Jun 24 23:32:18 kvs_stream: [kvs_module.c:771]Total number of active streaming sessions - only the ones that actually have streamed some data:4
Jun 24 23:32:18 kvs_stream: [kvs_module.c:772]Average session duration:114649672
Jun 24 23:32:18 kvs_stream: [kvs_module.c:773]Total number of buffered ACKs:49
Jun 24 23:32:18 kvs_stream: [kvs_module.c:774]Total number of received ACKs:48
Jun 24 23:32:18 kvs_stream: [kvs_module.c:775]Total number of persisted ACKs:48
Jun 24 23:32:18 kvs_stream: [kvs_module.c:776]Total number of error ACKs ACKs:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:777]Total number of dropped frames:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:778]Total number of latency pressure events:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:779]Total number of storage pressure events:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:780]Total number of Buffer pressure events:0
Jun 24 23:32:18 kvs_stream: [kvs_module.c:781]Total number of put frame call errors:0
Jun 24 23:32:18 kvs_stream: ret = 0 0 364
Jun 24 23:32:18 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:18 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:18 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:18 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:18 kvs_stream: postReadCallback(): Pausing CURL read for upload handle: 3
Jun 24 23:32:40 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 0, dts: 0, duration: 0, size: 0, trackId: 0, isKey 0
Jun 24 23:32:40 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 333 for stream handle 3
Jun 24 23:32:40 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 0. Bytes available: 333
Jun 24 23:32:40 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 400000 bytes 666 for stream handle 3
Jun 24 23:32:40 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 400000. Bytes available: 666
Jun 24 23:32:40 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 400000 bytes 750 for stream handle 3
Jun 24 23:32:40 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 4619216. Upload handle 3. Duration available in 100ns: 400000. Bytes available: 750
Jun 24 23:32:40 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 750 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:40 kvs_stream: postReadCallback(): Wrote 750 bytes to Kinesis Video. Upload stream handle: 3
Jun 24 23:32:40 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:40 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Pausing CURL read for upload handle: 3
Jun 24 23:32:41 kvs_stream: postWriteCallback(): postBodyStreamingWriteFunc (curl callback) invoked
Jun 24 23:32:41 kvs_stream: postWriteCallback(): Curl post body write function for stream with handle: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f and upload handle: 3 returned: {"EventType":"RECEIVED","FragmentTimecode":1624577536355,"FragmentNumber":"91343852333316229262149130853933369839129198306"}
Jun 24 23:32:41 kvs_stream: 
Jun 24 23:32:41 kvs_stream: postWriteCallback(): Processed ACK OK.
Jun 24 23:32:41 kvs_stream: postWriteCallback(): postBodyStreamingWriteFunc (curl callback) invoked
Jun 24 23:32:41 kvs_stream: postWriteCallback(): Curl post body write function for stream with handle: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f and upload handle: 3 returned: {"EventType":"PERSISTED","FragmentTimecode":1624577536355,"FragmentNumber":"91343852333316229262149130853933369839129198306"}
Jun 24 23:32:41 kvs_stream: 
Jun 24 23:32:41 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 0 for stream handle 3
Jun 24 23:32:41 kvs_stream: [kvs_module.c:160]Received fragment ack: Seq num 91343852333316229262149130853933369839129198306 Stream handle 4619216 Status PERSISTED
Jun 24 23:32:41 kvs_stream: Timestamp: 1624577536355 Stream Name: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f
Jun 24 23:32:41 kvs_stream: postWriteCallback(): Processed ACK OK.
Jun 24 23:32:41 kvs_stream: postReadCallback(): postBodyStreamingReadFunc (curl callback) invoked
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Get Stream data returned: buffer size: 65524 written bytes: 0 for upload handle: 3 current stream handle: 4619216
Jun 24 23:32:41 kvs_stream: postReadCallback(): Pausing CURL read for upload handle: 3
Jun 24 23:33:16 kvs_stream: curlCompleteSync(): curl perform failed for url https://s-4010bf70.kinesisvideo.us-west-2.amazonaws.com/putMedia with result Timeout was reached: Operation too slow. Less than 30 bytes/sec transferred the last 30 seconds
Jun 24 23:33:16 kvs_stream: curlCompleteSync(): HTTP Error 0 : Response: (null)
Jun 24 23:33:16 kvs_stream: Request URL: https://s-4010bf70.kinesisvideo.us-west-2.amazonaws.com/putMedia
Jun 24 23:33:16 kvs_stream: Request Headers:
Jun 24 23:33:16 kvs_stream:     Authorization: AWS4-HMAC-SHA256 Credential=[redacted] SignedHeaders=connection;host;transfer-encoding;user-agent;x-amz-date;x-amzn-fragment-acknowledgment-required;x-amzn-fragment-timecode-type;x-amzn-producer-start-timestamp;x-amzn-stream-name, Signature=[redacted]
Jun 24 23:33:16 kvs_stream:     connection: keep-alive
Jun 24 23:33:16 kvs_stream:     content-type: application/json
Jun 24 23:33:16 kvs_stream:     host: s-4010bf70.kinesisvideo.us-west-2.amazonaws.com
Jun 24 23:33:16 kvs_stream:     transfer-encoding: chunked
Jun 24 23:33:16 kvs_stream:     user-agent: AWS-SDK-KVS/3.0.0 GCC/4.7.2 Linux/3.10.14 mips
Jun 24 23:33:16 kvs_stream:     X-Amz-Date: 20210624T233156Z
Jun 24 23:33:16 kvs_stream: [truncated]     x-amz-security-token: [redacted]
Jun 24 23:33:16 kvs_stream:     x-amzn-fragment-acknowledgment-required: 1
Jun 24 23:33:16 kvs_stream:     x-amzn-fragment-timecode-type: ABSOLUTE
Jun 24 23:33:16 kvs_stream:     x-amzn-producer-start-timestamp: 1624577516.819
Jun 24 23:33:16 kvs_stream:     x-amzn-stream-name: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f
Jun 24 23:33:16 kvs_stream: putStreamCurlHandler(): Network thread for Kinesis Video stream: 87a1664f277abfac81bd23537e55d851c9585408c2f91b43332a1c16bf83fb9f with upload handle: 3 exited. http status: 0
Jun 24 23:33:16 kvs_stream: putStreamCurlHandler(): Stream with streamHandle 4619216 uploadHandle 3 has exited without triggering end-of-stream. Service call result: 599
Jun 24 23:33:16 kvs_stream: kinesisVideoStreamTerminated(): Stream 0x467bd0 terminated upload handle 3 with service call result 599.
Jun 24 23:33:16 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000100, Next state: 0x0000000000000200
Jun 24 23:55:25 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789228171070, dts: 16245789228171070, duration: 0, size: 82929, trackId: 1, isKey 1
Jun 24 23:55:25 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789228471520, dts: 16245789228471520, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:25 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 24 23:55:25 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000002

# ERROR OCCURS HERE

Jun 24 23:55:30 kvs_stream: blockingCurlCall(): Curl perform failed for url https://c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com/role-aliases/alias_iam_wyze_kvs_role/credentials with result Timeout was reached : Resolving timed out after 3000 milliseconds 
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x15000011 decoding timestamp: 16245789228471520 presentation timestamp: 16245789228471520

 # No more acks

Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789228709450, dts: 16245789228709450, duration: 0, size: 3983, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789228870790, dts: 16245789228870790, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789229274710, dts: 16245789229274710, duration: 0, size: 4200, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789229271800, dts: 16245789229271800, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789229675310, dts: 16245789229675310, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789229921660, dts: 16245789229921660, duration: 0, size: 4144, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789230071670, dts: 16245789230071670, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789230471260, dts: 16245789230471260, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789230606870, dts: 16245789230606870, duration: 0, size: 3976, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789230871280, dts: 16245789230871280, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789231246720, dts: 16245789231246720, duration: 0, size: 1989, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789231271510, dts: 16245789231271510, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789231697350, dts: 16245789231697350, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789231945360, dts: 16245789231945360, duration: 0, size: 4969, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789232071930, dts: 16245789232071930, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789232472250, dts: 16245789232472250, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789232578930, dts: 16245789232578930, duration: 0, size: 4143, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789232872630, dts: 16245789232872630, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789233276260, dts: 16245789233276260, duration: 0, size: 3720, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: [streamrcv.c:264][KVS] Put 20 frames.
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789233273270, dts: 16245789233273270, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789233677110, dts: 16245789233677110, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789233927690, dts: 16245789233927690, duration: 0, size: 3865, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789234072940, dts: 16245789234072940, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789234473320, dts: 16245789234473320, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789234598400, dts: 16245789234598400, duration: 0, size: 1807, trackId: 1, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789234873510, dts: 16245789234873510, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:30 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789235241450, dts: 16245789235241450, duration: 0, size: 4553, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789235273550, dts: 16245789235273550, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789235685960, dts: 16245789235685960, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789235954000, dts: 16245789235954000, duration: 0, size: 3292, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789236075060, dts: 16245789236075060, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789236473850, dts: 16245789236473850, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789236591450, dts: 16245789236591450, duration: 0, size: 4099, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789236873920, dts: 16245789236873920, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789237279020, dts: 16245789237279020, duration: 0, size: 3549, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789237276080, dts: 16245789237276080, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789237679690, dts: 16245789237679690, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789237940220, dts: 16245789237940220, duration: 0, size: 1687, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789238074740, dts: 16245789238074740, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: [streamrcv.c:264][KVS] Put 40 frames.
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789238479410, dts: 16245789238479410, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789238601680, dts: 16245789238601680, duration: 0, size: 4308, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789238874920, dts: 16245789238874920, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789239244140, dts: 16245789239244140, duration: 0, size: 3989, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789239275160, dts: 16245789239275160, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789239680250, dts: 16245789239680250, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789239951520, dts: 16245789239951520, duration: 0, size: 3651, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789240075740, dts: 16245789240075740, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789240475920, dts: 16245789240475920, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789240582600, dts: 16245789240582600, duration: 0, size: 3797, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789240875830, dts: 16245789240875830, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789241278480, dts: 16245789241278480, duration: 0, size: 2208, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789241276340, dts: 16245789241276340, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789241676180, dts: 16245789241676180, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789241931300, dts: 16245789241931300, duration: 0, size: 5822, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789242080300, dts: 16245789242080300, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789242476900, dts: 16245789242476900, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789242599230, dts: 16245789242599230, duration: 0, size: 4243, trackId: 1, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789242876900, dts: 16245789242876900, duration: 0, size: 320, trackId: 2, isKey 0
Jun 24 23:55:31 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16245789243252450, dts: 16245789243252450, duration: 0, size: 4843, trackId: 1, isKey 0

Have you been able to build out a unit test for this patch?

[schultetwin1]

Hi @hassanctech

Here are the logs with the extra logging:

Jun 29 10:40:38 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884363977640, dts: 16249884363977640, duration: 0, size: 89616, trackId: 1, isKey 1
Jun 29 10:40:38 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884364198840, dts: 16249884364198840, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 10:40:38 kvs_stream: checkStreamingTokenExpiration(): Enter 
Jun 29 10:40:38 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 10:40:38 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 29 10:40:38 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000002
Jun 29 10:41:03 kvs_stream: blockingCurlCall(): Curl perform failed for url https://************.credentials.iot.us-west-2.amazonaws.com/role-aliases/alias_iam_wyze_kvs_role/credentials with result Timeout was reached : Resolving timed out after 3000 milliseconds 
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Grace Period RESET to FALSE 
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE 
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x15000011
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x15000011 decoding timestamp: 16249884364198840 presentation timestamp: 16249884364198840
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884364643730, dts: 16249884364643730, duration: 0, size: 3739, trackId: 1, isKey 0
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Enter 
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884364600680, dts: 16249884364600680, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884365022080, dts: 16249884365022080, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884365302180, dts: 16249884365302180, duration: 0, size: 3816, trackId: 1, isKey 0
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 10:41:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16249884365400870, dts: 16249884365400870, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is TRUE
Jun 29 10:41:03 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000

It looks like the first call to streamTerminatedEvent fails as expected, and we reset gracePeriod, but the next call to streamTerminatedEvent does not do actually do any network transactions and just returns success.

So we are once again stuck with gracePeriod set to true, but no network attempts to refresh the credentials are occuring.

[hassanctech]

Thanks @schultetwin1, I've pinpointed the issue to here:

https://github.com/awslabs/amazon-kinesis-video-streams-pic/blob/master/src/client/src/StreamEvent.c#L745

Basically we're already in get endpoint state so we will terminate early. On the previous invocation we're in STOPPED state so we don't short circuit here. The criteria that being in one of those states means we're in the processing of spawning new uploading sessions is wrong I'm looking into what the correct criteria should be.

[schultetwin1]

I was able to test these latest changes. They seemed to allow the SDK to recover after the network connection came back!

Jun 29 14:32:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023202374620, dts: 16250023202374620, duration: 0, size: 89226, trackId: 1, isKey 1
Jun 29 14:32:03 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023202734380, dts: 16250023202734380, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:03 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:03 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 14:32:03 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 29 14:32:03 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000002

# First failure
Jun 29 14:32:19 kvs_stream: blockingCurlCall(): Curl perform failed for url https://c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com/role-aliases/alias_iam_wyze_kvs_role/credentials with result Timeout was reached : Resolving timed out after 3000 milliseconds 
Jun 29 14:32:19 kvs_stream: executeGetEndpointStreamState(): retStatus: 0x15000011
Jun 29 14:32:19 kvs_stream: checkStreamingTokenExpiration(): Grace Period RESET to FALSE
Jun 29 14:32:19 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:19 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x15000011
Jun 29 14:32:19 kvs_stream: putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x15000011 decoding timestamp: 16250023202734380 presentation timestamp: 16250023202734380

Jun 29 14:32:19 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023203017000, dts: 16250023203017000, duration: 0, size: 4522, trackId: 1, isKey 0
Jun 29 14:32:19 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:19 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 14:32:19 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000200
Jun 29 14:32:19 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 29 14:32:19 kvs_stream: fromAuthClientState(): Invalid auth token as it is expiring in less than 30 seconds

# Second failure
Jun 29 14:32:21 kvs_stream: blockingCurlCall(): Curl perform failed for url https://c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com/role-aliases/alias_iam_wyze_kvs_role/credentials with result Timeout was reached : Failed to connect to c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com port 443: Connection timed out 
Jun 29 14:32:21 kvs_stream: executeGetEndpointStreamState(): retStatus: 0x15000011
Jun 29 14:32:21 kvs_stream: checkStreamingTokenExpiration(): Grace Period RESET to FALSE
Jun 29 14:32:21 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:21 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x15000011
Jun 29 14:32:21 kvs_stream: putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x15000011 decoding timestamp: 16250023203017000 presentation timestamp: 16250023203017000

Jun 29 14:32:21 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023203131160, dts: 16250023203131160, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:21 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:21 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 14:32:21 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000200
Jun 29 14:32:21 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 29 14:32:21 kvs_stream: fromAuthClientState(): Invalid auth token as it is expiring in less than 30 seconds

# Third failure
Jun 29 14:32:24 kvs_stream: blockingCurlCall(): Curl perform failed for url https://c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com/role-aliases/alias_iam_wyze_kvs_role/credentials with result Timeout was reached : Failed to connect to c1ybkrkbr1j10x.credentials.iot.us-west-2.amazonaws.com port 443: Connection timed out 
Jun 29 14:32:24 kvs_stream: executeGetEndpointStreamState(): retStatus: 0x15000011
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Grace Period RESET to FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x15000011
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): Failed to submit frame to Kinesis Video client. status: 0x15000011 decoding timestamp: 16250023203131160 presentation timestamp: 16250023203131160

Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023203529780, dts: 16250023203529780, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023203719400, dts: 16250023203719400, duration: 0, size: 4669, trackId: 1, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Grace Period Set to TRUE
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000200
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000200, Next state: 0x0000000000000020
Jun 29 14:32:24 kvs_stream: fromAuthClientState(): Invalid auth token as it is expiring in less than 30 seconds

# Success!!
Jun 29 14:32:24 kvs_stream: convertTimestampToEpoch(): Expiration timestamp conversion into tm structure  121-5-29T22:32:24
Jun 29 14:32:24 kvs_stream: convertTimestampToEpoch(): Difference between current time and iot expiration is 3600
Jun 29 14:32:24 kvs_stream: parseIotResponse(): Iot credential expiration time 1625005944
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000002, Next state: 0x0000000000000040
Jun 29 14:32:24 kvs_stream: getStreamingEndpointCachingCurl(): Caching GetStreamingEndpoint API call
Jun 29 14:32:24 kvs_stream: getStreamingEndpointResultEvent(): Get streaming endpoint result event.
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000020, Next state: 0x0000000000000010
Jun 29 14:32:24 kvs_stream: getStreamingTokenResultEvent(): Get streaming token result event.
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000010, Next state: 0x0000000000000040
Jun 29 14:32:24 kvs_stream: [kvs_module.c:197]Stream Ready. Stream Handle: 7912400
Jun 29 14:32:24 kvs_stream: ret = 0 0 117
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000040, Next state: 0x0000000000000080
Jun 29 14:32:24 kvs_stream: putStreamResultEvent(): Put stream result event. New upload handle 1
Jun 29 14:32:24 kvs_stream: notifyDataAvailable(): Note data received: duration(100ns): 0 bytes 0 for stream handle 1
Jun 29 14:32:24 kvs_stream: notifyDataAvailable(): Failed to un-pause curl with error: 43. Curl object 0x7a5aa8
Jun 29 14:32:24 kvs_stream: defaultStreamDataAvailableCallback(): Reported streamDataAvailable callback for stream handle 7912400. Upload handle 1. Duration available in 100ns: 0. Bytes available: 0
Jun 29 14:32:24 kvs_stream: stepStateMachine(): State Machine - Current state: 0x0000000000000080, Next state: 0x0000000000000100
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023203929960, dts: 16250023203929960, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023204340180, dts: 16250023204340180, duration: 0, size: 2848, trackId: 1, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023204332160, dts: 16250023204332160, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023204746400, dts: 16250023204746400, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023205034220, dts: 16250023205034220, duration: 0, size: 4294, trackId: 1, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023205134060, dts: 16250023205134060, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023205535160, dts: 16250023205535160, duration: 0, size: 320, trackId: 2, isKey 0
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023205655480, dts: 16250023205655480, duration: 0, size: 4129, trackId: 1, isKey 0
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): Enter
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, gracePeriod is FALSE
Jun 29 14:32:24 kvs_stream: checkStreamingTokenExpiration(): In CleanUp, retStatus: 0x00000000
Jun 29 14:32:24 kvs_stream: putKinesisVideoFrame(): debug frame info pts: 16250023205935560, dts: 16250023205935560, duration: 0, size: 320, trackId: 2, isKey 0

Now, understood that if the network conditions were so bad this kept timing out then there would be nothing we could do for streaming actual video, but if network conditions recover after this point then streaming video will work again (instead of silently failing)!

[hassanctech]

Looks good but it's hard to reason about the behavior. Any plans on adding a targeted test?

@MushMal I've been having a hard time figuring out how to test this but yes definitely plan to add a targeted test as soon as we have one ready.