End of video speeds up then disappears, losing 30 or more minutes of video.

[tfabris]

Twice today I have observed a weird situation where the camera video "speeds up" at the end of the video like it was a time lapse and then that section is later lost completely.

Conditions:

• Daily recording of the video has gotten "split" because of a network problem which caused a stream bounce.
• For example: This video: https://www.youtube.com/watch?v=bpp16rzH-2s
• Camera turns on at 5:20am.
• Video stream records on Youtube fine until about 10:56 am approximately, then the "problem" with the video happens at that point.
• When watching the archived version of the video shortly after it was recorded (and YouTube no longer says "PROCESSING..." though I know that's often a lie), I see that the video data that exists after 10:56 am is super-sped-up like it was a time lapse. With minutes flying by in seconds.
• The video then stops at the "split" point where the stream got bounced.
• I look at the Synology logs and it says that there was a network problem and the stream indeed had to be bounced, but, the network problem and the bounce occurred at 11:33am, half an hour after the video stream started showing issues.
• However, Later, I look back at the archived video, this time after the processing was REALLY done (not the "lie" when the word "PROCESSING..." disappears) and now, the "speedy up" part at the end, that last half hour of speeded up video, is now gone completely. The video plays the entire normal-speed part up to 10:56 am and the ends at that point.
• Thus the video did not end at 11:33 am, I lost more than 30 minutes of the video.
• I also note that the bounce time, 11:33 am, is the time that YouTube reports that the video ended.
• However the LENGTH of the video itself is listed in YouTube as 5:35:58, which if my math is correct, is the shorter time length.
• Viewing this video later, the next day, after giving it time for even more processing, it still has the same effect - total runtime now reads 5:35:57 and the video still ends at 10:56 am This video did not "Fix itself" like the one below.
• The next video after the split starts properly, when you would expect it, at approx 11:34 am.

I had this happen again, with the next split section, the one that started at 11:34 am:

• This video: https://www.youtube.com/watch?v=olVsVsgFtOU
• Recorded fine for a few hours and then split at a network trouble bounce.
• Synology logs say that the bounce happened at 5:36pm.
• Initially viewing the youtube video archive, the speedy timelapse thing at the end, the "speedy up" part starts at about 2:21 pm on the baked-in clock, and the video ends at 5:36 pm.
• YouTube says that the video length is 2:49:17 which is the shorter length.
• UPDATE: Later, when viewing this video, I see that the video now runs the correct full length, for a total runtime of 5:59:47. The "speedy up" part that I noticed before, was merely an artifact of the "PROCESSING..." lie. It wasn't really done processing, and merely waiting for the processing to complete fixed it.

[tfabris]

THEORY:

• It is possible that the times where I observed the "speedy up time lapse" problem were the times where I was viewing the Synology "Timeline" program and looking at the video happening today on the NAS directly from the timeline.
• It is possible that using the "Timeline" program may interfere with the "Live Broadcast" feature.

TO DO:

• See if this can be confirmed and then report it as a bug, and also avoid doing this on the NAS.

[tfabris]

My theory was incorrect. The second occurrence of the speedy up part was during my Timeline views, but the archive ended up fixing itself and all video was there.

Later, on the 19th, I spent a lot of time in the 3pm hour looking at the Timeline and it didn't mess up the stream at all.

[tfabris]

I'm going to close this bug because I haven't seen a recurrence. It may have been a particular YouTube mess-up which was a one-off. Reopen if you see it again.

[tfabris]

I think this has been fixed by one of the attempted fixes for issue #23.

Example:

Video: 2019-05-21 https://youtu.be/Ne1XrvA0Y4Q

Video plays fine for most of the day up until 6:13:08 pm, at which point it starts jumping and fast forwarding from 6:13:09 pm up until 6:17:something pm at which point it ends due to a bounce.

Here is the log of that bounce:

Error 2019-05-21 18:19:10 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime
Info  2019-05-21 18:19:10 CrowCam Controller - The network is up, but the YouTube stream is down. Pausing to give it a chance to come up. Inner stream test loop, retry attempt 1 of 3 . Sleeping 30 seconds before trying again.
Error 2019-05-21 18:19:42 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  2019-05-21 18:19:42 CrowCam Controller - The network is up, but the YouTube stream is down. Pausing to give it a chance to come up. Inner stream test loop, retry attempt 2 of 3 . Sleeping 30 seconds before trying again.
Error 2019-05-21 18:20:13 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Error 2019-05-21 18:20:13 CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  2019-05-21 18:20:15 CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  2019-05-21 18:21:50 CrowCam Controller - Done bouncing YouTube stream.

The log didn't catch the issue until about six minutes after the issue started occurring. Possibly because it doesn't check for the problem every moment, it only starts checking for the problem about once every five minutes. That explains the gap where it didn't notice the issue right away. But once it started checking, boy howdy did it catch a valid issue and did a valid bounce.

The subsequent video stream after the bounce is: https://youtu.be/jLAipmnPNnc It starts at 6:21:53 pm and it's playing perfectly fine at one second per second up until EOD.

[tfabris]

My code correctly detects this problem when it occurs, and it bounces the stream.

However, lately, bouncing the stream doesn't seem to fix the problem as often as it did before. After a bounce, the stream still gets "VideoIngestionFasterThanRealtime" error messages, and then the video has to bounce again. This fills the video playback history with a bunch of separated video segments which are only a few minutes long each. Many of these segments exhibit the "fast zoomy time scale" problem which is emblematic of this bug. But some of them don't.

Things I have done so far, to try to fix the problem:

• Increase the hysteresis amount before it bounces the stream. The theory was: Maybe the first detection of "VideoIngestionFasterThanRealtime" was correct, but subsequent ones are red herrings caused by the YouTube API hanging onto the error message longer than it should. However, after increasing the hysteresis to nearly ten minutes, it's still a problem. Also, when I look at the "short" segments which are after a couple of bounces (between bounces), I see that the fast zoomy problem is usually there. If this were a red herring problem, then they would be primarily "good" video segments, and I'm not seeing that.
• Called Comcast and told them my internet was getting connection-drop problems. This is technically true, we were also having a lot of internet drops at the same time, where I had to bounce the cable modem to get the network to come back up. This also coincided with comcast claiming that they were increasing our internet speed (in an email). Comcast tech came out, and re-did the plug ends on all my coax cables, and replaced some signal splitters (in the cupboard and at the street), and this improved the SNR on the cable a bit. The jury is still out as to whether this fixed the internet drops, but it definitely didn't fix the fast zoomy bug.
• Updated the firmware and refreshed all the settings on the IP camera.

Things to try:

• Is this due to CrowCamKeepAlive not really working any more? On days where I sit there and watch the video from a browser window, it seems to happen less often. Is there a chance that CrowCamKeepAlive has stopped being effective and this is the side effect? Not sure.
• Look more closely at which segments show the fast zoomy problem, and which ones don't. Compare that to the logs. See if you can find any sort of correlation.
• Investigate to see if it would help to bounce everything, not just the video stream, when this occurs? Try bouncing:
  • The IP camera.
  • The cable modem.
  • The DHCP router.
  • The Synology Surveillance Station service.
  • The Synology device itself.
  • The YouTube channel's stream itself? Can that be done? I think most of the instructions say to stop it at your streamer source (in my case, the "Live Broadcast" setting) to stop the stream. Maybe this is not possible.
  • I had tried manually bouncing some of those things when I observed the problem, and it didn't seem to fix it, but it still deserves some more investigation.
• Recheck the wiring to the IP camera.
• Investigate a fancier IP camera.

[tfabris]

Note: Observation that I see on the camera itself while the issue is occurring:

• Video is freezing and only delivering video in spurts.
• Looking at the "seconds" timestamp counter baked into the camera, the counter only updates every 2-3 seconds.
• Observing closely, this is not a case of "one frame is transmitted every 2-3 seconds" rather, this is "video runs in spurts and pauses every couple seconds".
• When the issue is occurring "live", when I observe the camera directly with the Reolink client application, the video is just fine. Updating every second with no stutter. This includes watching the video over LTE so that it's not even on my LAN at all.

So the problem doesn't seem to be the camera. Is it the synology?

To investigate: is there a way to have the camera squirt directly to YouTube without the Synology in the middle?

[tfabris]

More thoughts:

• It can't be a general flakiness problem with the internet service. If it were, then viewing the camera directly with the Reolink client would also display the issue. And it's not.
• It could still be a more specific thing with the internet service if Comcast is doing a specific clampdown on upstream video delivery.
• Synology is still suspect. Wonder if there's any sort of CPU monitoring I can record and see if Synology burnchurn corresponds with fscked up video stream?

To do:

• Try reducing the upstream speed. Set it to a lower value on both the camera and in the synology settings. Right now it's 3kbps, try 2kbps or 1kbps? Does that result in too-poor quality?
• More investigations of direct camera squirt technology. Or alternate squirt technology. Might need a different brand of camera for that.
• Investigate things you might be able to do on the Synology side that might improve it. Example: Is synology having to re-encode the video before sending up the pipe? Right now it's set to Video format: H.264. Perhaps there is a setting to set the camera to default to RSTP format which would allow Synology to directsquirt? Maybe? Looks like "not" when I look at their docs.
• Try other things to improve the stream on the Synology side. For example setting stream type to UDP instead of TCP, or changing the keep alive setting, and other things. This is documented here: https://www.synology.com/en-us/knowledgebase/Surveillance/help/SurveillanceStation/camera_settings_advanced

[tfabris]

Tried changing some of the camera settings in Synology Surveillance Station:

• Video format cannot be changed, my only available option is H.264.
• Reduced bandwidth to 2048.
• Under Device Settings-Advanced I experimentally changed these settings:
  • Transport Protocol: UDP
  • Keep Alive Method: GET_PARAMETER
  • Streaming information source: Streaming

To do:

• No direct camera squirt options exist in the RLC-420 firmware controls. Consider finding a third party squirter, either something that can run directly on the Synology, or on a local PC (as a temporary experiment) to see if that fixes it.

[tfabris]

This morning's feed (2019-09-24) has been doing well. The problem did not recur for the entire morning, which is very promising (though more bake time is needed to be sure). The issue usually recurs multiple times each morning, and today, no problems yet. I made the following changes yesterday (2019-09-23), so it's likely to be one of these things that fixed it:

• In the camera's own settings, and in the Surveillance Station settings, reduced camera streaming bandwidth usage to 2048.
• In Surveillance Station, IP Camera, Device Settings, Advanced:
  • Transport Protocol: UDP
  • Keep Alive Method: GET_PARAMETER
  • Streaming information source: Streaming

My first guess is that it was the bandwidth setting, since I'm expecting that the other three settings only govern the communication between the camera and the Synology, something that's never been, an issue, and isn't currently an issue. That leaves pretty much the bandwidth.

Though theoretically it could possibly be the UDP setting. I could see how, if TCP transport caused the video to come in "hitches and spurts" instead of a steady stream of UDP packets, such a hitchyness could get forwarded up to the YouTube server too. That would tend to trigger the VideoIngestionFasterThanRealtime issue. So UDP vs TCP is also a suspect.

With regards to video quality, 2048 is not that bad compared to 3072, but I'd really like to keep it at 3072 if I can. The extra clarity is worth it to me, if we can swing it. So it's important to try to narrow this down more solidly.

To do:

• See if the problem recurs if you set the three Surveillance Station settings back to their original defaults. Try this on a day you're at home all day and can monitor it.
• If setting the three Surveillance Station settings back to their original settings makes the problem recur, then:
  • Try setting just the transport protocol to UDP, and see if that fixes the issue again.
  • If setting the transport protocol to UDP fixes the issue, then try upping the bandwidth to 3072 again, and see if we can leave it at UDP+3072 to get a steady stream.
• If setting the three Surveillance Station settings back to their original settings did not make the problem recur, then:
  • Try temporarily upping the bandwidth to 3072 and see if it makes the problem recur, to diagnose for sure that the bandwidth was indeed the root cause. Once the problem repros, put it back down to 2048 and leave it there.

[tfabris]

Last night I set the following back to their original settings: Surveillance Station, IP Camera, Device Settings, Advanced:

• Transport Protocol: TCP
• Keep Alive Method: OPTIONS (Default)
• Streaming information source: RSTP

I left the camera's own bandwidth setting, and the Surveillance Station bandwidth setting, at 2048.

Everything is still working fine this morning. Conclusion: Having the bandwidth at 3072 was the root of the problem all along. I only have ±6mbps theoretical max upstream available anyway. Something changed at Comcast recently which caused 3072 upstream to become an unexpected problem.

I'll update my dox and close this issue as "fixed".

EDIT: Later, looking back, the resulting saved archive video of this one, on 2019-09-26 from sunrise until the VideoIngestionFasterThanRealtime reboot at 10:30 am, was not good. Even though it seemed fine "live", there was something wrong with the archive. The video was "stop-start", playing a second of video then a second of freeze, and repeating, the whole time. And the script didn't get an error for any of it until about 10:30 am ish. So having it set to TCP/2048 wasn't the perfect solution.

[tfabris]

Today I saw one instance of VideoIngestionFasterThanRealtime at about 10:30 am.

So it could be that the problem might not have been the bandwidth. Trying the following settings (starting 2019-09-26 ±2:30pm):

Surveillance Station, IP Camera, Device Settings, Advanced:

• Transport Protocol: UDP Camera and Synology:
• Bandwidth: 3072

[tfabris]

On 2017-09-27 at 11:17 am:

• Settings: 3072 with UDP
• Archived video shows a problem with the zoomy-fast video happening, starting at 11:17 am.
• No VideoIngestionFasterThanRealtime was detected. No errors at all were in the log at that time.
• Issue continued nonstop and does not fix itself.
• Until the normal midday bounce occurred at 2:33 pm. At which point it was fixed.
• NOTE: The midday bounce did NOT split the stream. The video archive just got the zoomy fast problem solved at that point.

2017-09-27 at 4:47pm

• Settings: 3072 with UDP
• VideoIngestionFasterThanRealtime that happened at 4:47pm in the afternoon shift.

To do: Try some other settings to see if this can be fixed.

[tfabris]

2019-09-29 10:48 am - Tried setting everything back to:

Surveillance Station, IP Camera, Device Settings, Advanced:

• Transport Protocol: UDP
• Keep Alive Method: OPTIONS (default)
• Streaming information source: RSTP

Camera and Synology:

• Bandwidth: 2048

Also rebooted camera and Synology at 10:54 am for good measure.

[tfabris]

A similar issue occurred with similar but not identical symptoms:

• Link to example video: https://bit.ly/2oJJR83
• Time start: 2019-09-29 at 5:51 pm.
• Time end: 2019-09-29 at 6:31 pm - Script rebooted the stream I think (check logs: Yes).
• Video starts out as being "choppy" - Plays for 1 second then freezes for 1 second, alternately.
• Eventually the video goes to the fast zoomy problem that is emblematic of the "VideoIngestionFasterThanRealtime" issue.
• The video stream is eventually restarted, fixing the problem for the next video in the archive.

One PARTICULARLY INTERESTING NOTE:

• At this point in the video: https://bit.ly/2oHMCqq
• It's in the middle of doing the fast zoomy thing. Has been doing so for quite a while.
• Then, right before the stream split, at 6:31:50 pm - IT STARTS WORKING FINE AGAIN.
• Question: Did it simply fix itself coincidentally there, or, does the stream split solve the problem instantly, even before the split "takes hold"?
• Theory: Maybe the video ingestion packets are getting out of order, and that's what's causing the problem? Then a "stop" of the stream packets might cause the video to reassemble correctly at the topend briefly, before it cuts out completely?
• If true, can we fix this with a FAST stream bounce (ie., doesn't result in a stream split) in the "VideoIngestionFasterThanRealtime" case?

[tfabris]

Added long and short bounce durations, and reduced the amount of hysteresis on stream issues.

Now it will only bounce the stream for 5 seconds for network blips and stream issues. Let's see if this makes things better?

Hopefully this will:

• When VideoIngestionFasterThanRealtime occurs, it won't split the stream.
• When VideoIngestionFasterThanRealtime occurs, it will get corrected much sooner.
• When network downage occurs, if it's a real network downage, we shouldn't see a difference because the stream would have gotten split anyway.
• When network downage occurs, if it's a false alarm, then we should just see a brief blip in the stream.

[tfabris]

New code seems to have worked. This morning 2019-10-01 at 8:08:43 am, it did a bounce due to a detection of VideoIngestionFasterThanRealtime. The detection was short (1 min hysteresis starting at 8:07), and the bounce was short (5 sec), with the video dropping out only from 8:08:35 to 8:08:51 in the archive, but keeping the same video stream.

In addition, this fixed audio desynchronization as described in issue #14. Though the audio desynch problem was not detected by the script in any way (it had been going on for quite a while before the bounce), the short bounce fixed the issue at the time.

Also I did not see any video problems when the bounce occurred, only the audio issue.

[tfabris]

New bounce code is working super well for the last few days. Closing issue.

[tfabris]

Experimenting with putting the speed up to 3072 again, leaving everything else as-is (UDP mode is on).

To do:

• See if this works OK with the existing bounce code. Look at logs after a few days of running at 3072/UDP and see if the bounces are worse or the same.

[tfabris]

Noticed some troubles with start/stop video this evening and went back down to 1080p/2048/UDP to make things work smoother.

[tfabris]

The larger bandwidth is not the sole reason for the zoomy fast VideoIngestionFasterThanRealtime problem. It was set to 1080p/2048/UDP last night, but this morning there were a ton of VideoIngestionFasterThanRealtime bounces.

Doing the short 5-second bounces indeed seems to fix the zoomy fast instances. When a 5-second bounce occurs, if I look at the archived video, I see the zoomy fast problem right before the bounce, then it's corrected by the bounce. So it helps.

Also I think setting it to the lower bandwidth might possibly still decrease the overall long-term frequency of the zoomy fast problem. It just definitely doesn't fix it completely.

[tfabris]

I tried 2 second bounces and got a lot of instances where the zoomy fast problem did not get fixed. It's at 4 seconds now and doing OK, with the zoomy fast problem getting fixed commonly by the four second bounces.

I found that the zoomy fast problem tends to coincide with Comcast network problems. I think this is all down to just "bad comcast" and I've worked around it as best I can for now.