Live feed hangs and gets "reload" icon sometimes.

Sometimes when viewing the live feed from my desk at work, it will hang in the following way:

Loading or refreshing the Youtube "live" page, it plays what looks like a good video feed.
However if you look closely at the camera time stamp, you see that the time of day is not up to date.
It plays the video for several seconds then it hits a "Spinning death arrow" reload icon which just sits there spinning.
Reloading the page does not solve the problem.
Rebooting the camera solves the problem.

Consider:

Coincidence that it's me connecting to the stream that caused the problem? When it happens, the "moment of spinny death" seems to coincide with my first loadup of the page from my work desk. This might be a coincidence and not based on reality. But it really did coincide for sure: There was a crow visit just moments before I logged in, and my scrollback into the DVR history revealed the crow as mere moments short of realtime. Then looking at the DVR feed I see that the problem occurs just after the crow visit.

To do:

Investigate Synology logs for this timestamp: 2019-05-03 11:25am. That is when the spinny death icon occurred today, that is the timestamp that was on the camera at the time. I rebooted the camera at 11:39am and it recovered shortly after the reboot.
Look at the final archive video of that time. The video DVR feed (during "live view day") timejumps from 11:25am to 11:39am. See if the archive does the same. If the archive is fine, but the DVR was spinnydeath/timejump, then it's entirely YouTube's problem.

I looked at the logs. 2019-05-03 11:25am contains one entry of:

"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 6 . Sleeping 15 seconds before trying again." Followed by:
"CrowCam Controller - Live stream came back up." After that, I see the reboot of the camera in the logs at 11:39. I saw no problems in the Surveillance Station logs.

Historical records:

In the feed archive on YouTybe I see it jump from 11:25 to 11:39 just like I did in the DVR stream on the "day of".
In the Surveillance Station video archive, I see no problems. I see the crow visit at 11:23, and I see a full uninterrupted video stream from 11:24:00 through 11:38:28 where I reboot the camera. Then a tiny gap for the camera reboot and then it resumes with no changes.

Conclusions:

Either YouTube is screwing up, or the "Live Broadcast" feature is screwing up. Hard to tell which it is. I am leaning towards YouTube because the stream tester script detected a "blip" of some kind at 11:25, but YouTube site tried to recover and the tester couldn't tell it was down.

Did it again today.

Death time: 2019-05-04 10:30:09am Discovered and rebooted camera: 5:10pm Nothing in Surveillance Station logs except for my reboot. Nothing in Synology logs this time (there were some blips at 11am but nothing at 10:30). Rebooting the camera fixed it.

Similar issue just happened 2019-05-05 6:24pm:

I watched the ChromeCast give an error that the "network was down", twice, and my internet on my laptop was pretty flaky.
YouTube live feed dropped completely (not the same symptom as the original bug post, this time it was fully down, titlecard showing and everything).
A "network error" did not trigger in CrowCam.sh, apparently it was so brief that it didn't fall in the checking range of that program.
A "network is up but the stream is down" error did trigger in CrowCam.sh, but bouncing the stream did not fix it, the stream stayed down after that bounce.
I tried bouncing the camera around the same time as CrowCam.sh was bouncing the stream, and it then resulted in the issue at the top of this post (spinny death icon).

So, whatever is causing this shit, it's an indirect result of a flaky network.

Possible cause: Torrey started uploading videos from her iPad around that time. Maybe a saturated upstream channel could cause this?

It took several tries of rebooting the camera and the live stream to get things to come back and work. Until then it just kept either going to "No Stream" or "Spinny death stream".

Trying (wondering if this may also help issue #14):

Editing the "Camera - Advanced" setting in Surveillance Station: Setting "Transport Protocol" to "TCP" (default is Auto).
Note: Cannot change "Keep Alive Method" (default is "Options", and the other option doesn't work).

Issue recurred at approx 6:34 am on Wed 2019-05-08 (spinny death icon with camera displaying that time stamp). Discovered the issue and rebooted camera at approx 7:39 am. After that, the stream didn't come back cleanly, and also the camera got unexpectedly reset to 1080p/5mbps instead of my desired 1296p/3mbps setting. It required resetting the camera, bouncing my local routers, and multiple automatic restarts of the stream by CrowCam.sh. In the end the stream didn't come back until I fixed the stream key, which had gotten reset due to issue #24.

Nothing odd in the surveillance station logs. Synology logs show that CrowCam.sh did not see any network blip and did not take any actions. Synology logs show that CrowCam.sh saw a stream blip, at 6:23:34 am, but that it came back up again 30 seconds later.

So changing the transport protocol to TCP didn't solve the issue.

And idea to fix this (assuming that it's just the temporary spinnydeath and not a full stream key change) would be to have CrowCam.sh detect when the last update was made to the live stream, and bounce the stream if it's been too long since the last update. There might be a way to do this via the YouTube API. We're looking specifically for the variable "boundStreamLastUpdateTimeMs" in the YouTube API. Please see issue #26 for a possible way to handle this programmatically.

boundStreamLastUpdateTimeMs was not the correct way to check this. However there may be some other API calls we can use for this. For instance look at LiveStreams: https://developers.google.com/youtube/v3/live/docs/liveStreams#resource

"status": {
    "streamStatus": string,
    "healthStatus": {
      "status": string,
      "lastUpdateTimeSeconds": unsigned long,
      "configurationIssues": [
        {
          "type": string,
          "severity": string,
          "reason": string,
          "description": string
        }
      ]
    }
  },

The actual output looks like this, and it seems that "lastUpdateTimeSeconds" for the healthStatus is not being sent any more. It's in the docs but I'm not seeing it in the output.

However the "status" of "healthStatus" object could maybe be useful? I need to run the WIP test code (StreamStatus-WIP.sh) the next time I see a spinny death hang and try to find out if something useful is displayed here when the stream is having problems.

{
 "kind": "youtube#liveStreamListResponse",
 "etag": "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
 "pageInfo": {
  "totalResults": 0,
  "resultsPerPage": 5
 },
 "items": [
  {
   "kind": "youtube#liveStream",
   "etag": "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
   "id": "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
   "status": {
    "streamStatus": "active",
    "healthStatus": {
     "status": "ok",
     "configurationIssues": [
      {
       "type": "videoResolutionSuboptimal",
       "severity": "warning",
       "reason": "Check resolution",
       "description": "Please check the video resolution. The current resolution is (2304x1296), which is not optimal."
      },
      {
       "type": "audioBitrateLow",
       "severity": "info",
       "reason": "Check audio settings",
       "description": "The audio stream's current bitrate (0) is lower than the recommended bitrate. We recommend that you use an audio stream bitrate of 128 Kbps."
      },
      {
       "type": "audioSampleRate",
       "severity": "info",
       "reason": "Check audio settings",
       "description": "The current sample rate is 0. The recommended sample rates are 44.1kHz and 48kHz."
      }
     ]
    }
   }
  }
 ]
}.

I have working code in place which is hoping that it will help this. Need to see if this lives for a long time without issue, and if so, we can close this bug. Give it a few weeks.

Currently: The code is using the "status" field of the "status" part of the "LiveStreams" resource, and also the "healthStatus" field, as described here: https://developers.google.com/youtube/v3/live/docs/liveStreams#resource Those seem to be the only two things that give me the status of the actual stream. I can't find anything else.

The code currently also uses YouTube-DL to check if the stream is up, too. A failure of either one (API or YouTube-DL) will be considered a stream failure.

If you ever get a situation where:

Log says that the variables for streamStatus and/or healthStatus were successfully retrieved but reported failure values (like healthStatus: noData or streamStatus: error), and,
Log does not complain about YouTube-DL getting a bad result, Then it's possible that you may have fixed the bug: The new API code is better than YouTube-DL and may have caught the issue.

The code ran in production for only a day, and as the end of the day approached, it busted a 10,000-a-day quota limit on the YouTube API.

I have removed the code which queried for the stream status. Shame, because it seemed to work so well.

Some ideas for how to fix this:

Implement fix for issue #29 - Make my API queries stop querying if one of them fails, so that it doesn't keep hammering. Not sure if this will fix it, but needs to be done anyway.
See if there is a way to make the stream uptime query happen less frequently. Something as simple as running the timed job less frequently could do it, though maybe there's a more clever way I can implement something like that.

Note: Look at your Google Developer API account to monitor the quota usage in a given day, there's a "quota" tab on the left side: https://console.developers.google.com/apis/api/youtube.googleapis.com/quotas?project=crowcam

Checked in new code: Attempt to address issues #23 and #29:

Reinstate the API query for testing the stream
Reduce the number of times that the Test_Stream hysteresis retest loop runs. Should reduce the number of quota points used when the stream is being troublesome.
Change the run frequency of CrowCam.sh from 1 minute to 2 minutes. Should halve the number of quota points used in a day.
Remove the code which retrieved the timestamp of the last YouTube configuration change, should save on quota points somewhat.
Do not continue to query the YouTube API if the necessary API values were not retrieved.

Need to test this on production system and see how it does for a day.

Happened really badly on 2019-05-18 at 8:14:21 am.

For the entire day until I came home it was stuck with spinny death at 8:14:21am showing a short clip. Later, after an unusual amount of time spend on the "processing..." stage, the final archived video goes from startup to 8:14am and then terminates. It is this video: https://youtu.be/EtU5Dvnaj-g?t=10701

Live stream health error read "Bad: Check Video Settings - Your encoder is sending data faster than realtime (multipleseconds of video each second). You must rate limit your livevideo upload to approximately 1 second of video each second."

Continuing to investigate this issue. Synology log info coming up in the next comment.

Synology log shows that we had a "stream down" at 7:20 am and at 8:43 am, once each, but then the stream came back up immediately after each of those checks according to the script. Neither of those times coincides with the 8:14am hang.

At 9:00 am it got an error where it couldn't get boundStreamId: CrowCam Controller - The liveBroadcastOutput was { "error": { "code": 500, "message": null } } . -- But then there were no more errors after that.

The stream key/name has not changed, it is still the same thing at this time as has been since 2019-05-08 (1.5 weeks so far without a stream key clobber event).

When I run the CrowCam.sh locally in debug mode, the output looks perfectly fine.

However the "encoder sending data faster than realtime" thing is indeed showing up in the YouTube API status output, so I'm going to try triggering on that:

  "configurationIssues": [
      {
       "type": "videoIngestionFasterThanRealtime",
       "severity": "error",
       "reason": "Check video settings",
       "description": "Your encoder is sending data faster than realtime (multipleseconds of video each second). You must rate limit your livevideo upload to approximately 1 second of video each second."
      },

The most recent checkin did indeed fix the issue when I ran a local debug version of the script. It detected the string "videoIngestionFasterThanRealtime" multiple times in a row and bounced the stream. Afterwards, the stream came back up and seemed steady for at least the 10 minutes or so that I observed it.

To do: Look at the stream archive and the Synology logs tomorrow and see if everything worked as expected after the bounce. The bounce was completed successfully at 2019-05-18 5:10 pm.

Look for:

How does the synology log look for the evening?
Did the stream continue lasting just fine or did the problem recur?
If the problem recurred, what errors showed in the Synology log?

Also note:

Regarding this decision:
- Should the code should continue to include YouTube-DL?
- Is the YouTube API code enough to detect the situations that YouTube-DL detected before?

Well I noticed that some of my messages were stiil "dbg" level so I'm not 100 percent certain about this. I see that today (2019-05-18), during the approximate "problem" time, there were two detections of a problem by YouTube-DL, and zero detections of a problem by the YouTube API. I can tell because the YouTube API would have printed some "err" messages, and those didn't print. I only got the "stream is down" messages that were the result of failure detections by YouTube-DL.

HOWEVER... Both of those detections by YouTube-DL were within the Hysteresis noise floor, and did not result in a stream bounce.

So my conclusion so far is that YouTube-DL is either:

Totally flaky due to being too sensitive, and should be discarded, or,
More sensitive than the API checks and should be kept.

Not sure about the conclusion yet. I'll let the script run for a while more with the YouTube-DL code printing out "err" messages if it encounters a problem, and see how we do long term.

I looked at the camera settings after the recurrence of issue #23 and found out:

My local Reolink "App" on my iPhone had forgotten its login password and I had to re-enter it. The password had not changed on the camera itself, it's just that the Reolink App did not have it built in any more and it was saying the password was wrong. When I typed in the right password, the app connected fine to the existing camera.
The camera had been reset to 1080p but the stream bandwith was still 3mbps as it should have been.

Had a situation where the stream went down today and the script properly recovered, first with the old code then with the new code. It went like this:

Network was up but stream was down.
Both YouTube-DL code and the API code reported that the stream was down.
The stream got bounced.
After the bounce, the new error "videoIngestionFasterThanRealtime" occurred - This time only the new API code caught it; The YouTube-DL code didn't notice anything wrong.
The new code correctly compensated for it and bounced the stream a second time.
After the second bounce the stream worked correctly.

Relevant log entries below.

Error System 2019-05-19 13:14:59 System CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error System 2019-05-19 13:14:59 System CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Error System 2019-05-19 13:15:12 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1, live stream is down.
Error System 2019-05-19 13:15:12 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl returned an error message string, live stream is down.
Info  System 2019-05-19 13:15:12 System 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 System 2019-05-19 13:15:43 System CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error System 2019-05-19 13:15:44 System CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Error System 2019-05-19 13:15:55 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1, live stream is down.
Error System 2019-05-19 13:15:55 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl returned an error message string, live stream is down.
Info  System 2019-05-19 13:15:55 System 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 System 2019-05-19 13:16:26 System CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error System 2019-05-19 13:16:26 System CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Error System 2019-05-19 13:16:38 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1, live stream is down.
Error System 2019-05-19 13:16:38 System CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl returned an error message string, live stream is down.
Error System 2019-05-19 13:16:38 System CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  System 2019-05-19 13:16:39 System CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  System 2019-05-19 13:18:14 System CrowCam Controller - Done bouncing YouTube stream.
Error System 2019-05-19 13:24:18 System CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  System 2019-05-19 13:24:32 System 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 System 2019-05-19 13:25:04 System CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  System 2019-05-19 13:25:17 System 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 System 2019-05-19 13:25:48 System CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Error System 2019-05-19 13:26:04 System CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  System 2019-05-19 13:26:05 System CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  System 2019-05-19 13:27:41 System CrowCam Controller - Done bouncing YouTube stream.

This makes me want to try it without using YouTube-DL as the stream-upness-checker, and rely entirely on the API to decide on stream upness.

I'm going to tentatively comment out the YouTube-DL code as it relates to stream-upness-checking. However, before checking it into production, look at the Synology logs for 2019-05-19, there are at least three stream bounces on that day (the one cited in the prior comment and at least two others as well). Check to see if these are legit, and that the logs look correct for them.

Interesting note about the video archive of the stream with the bounce on 2019-05-19 at 1:18 pm and then again at 1:26 pm (log entries are a couple of comments up in this thread):

I watched the resulting archive video on YouTube.
The video looked fine from 1:18 until 1:26 pm.
The video does not split during the second bounce at 1:26pm.
The video simply skips the clock time from 1:25:55 pm to 1:27:44 pm.

Conclusions from this:

I had been wondering about whether or not the 95-second "hole" that I've programmed into the bounce code ("sleep 95") is too much time or not. Nope! It's in fact right on the edge of the time needed to actually split the stream. Because this time the stream didn't split but it usually splits.
The "videoIngestionFasterThanRealtime" message might be a red herring sometimes.
The "videoIngestionFasterThanRealtime" message wasn't a red herring on Saturday 2019-05-18 when I added the code to bounce it based on that message.
It's probably good to keep the code because sometimes it fixes things, and when it's a red herring, maybe it's not a huge problem.

To do:

Still need to look at logs for 2019-05-19 to see if the other bounces were legit.
Video segments from that day are:
- Video runs 2019-05-19 from 5:15:06 am to 1:11:06 pm https://youtu.be/ynFcxTtbNHY
- Video runs 2019-05-19 from 1:18:18 pm to 3:53:12 pm: https://youtu.be/iZSK0GInTxM
  - Includes the known "skip" from 1:25:55 pm to 1:27:44 pm.
- Video runs 2019-05-19 from 4:04:43 pm to 6:02:03 pm: https://youtu.be/wEvEfAIJwaE
- Video runs 2019-05-19 from 6:03:55 pm to 9:06:04 pm: https://youtu.be/L4h7J4iqI_M

The remaining two bounces on 2019-05-19 are looking legit, and in addition, the API checker code caught the issue while the YouTube-DL checker didn't catch it.

The stream died at 2019-05-19 at 3:53:12 pm, and the API checker code started complaining at 3:59:55 pm, while the YouTube-DL code sat there doing nothing. The bounce happened at 4:01:50 pm. Then the stream went down at 6:02:03 pm, and the log shows that the API checker code started complaining at 6:00:12 pm and performed the bounce at 6:02:16 pm.

Based on this, I will continue with my plan of removing the YouTube-DL code from CrowCam.sh (leaving it in CrowCamKeepAlive.sh).

Logs from the later two bounces:

Info  SYSTEM 2019-05-19 14:05:56 SYSTEM CrowCam Controller - Retrieved sunrise/sunset times from Google: 5:26 AM/8:46 PM.
Error SYSTEM 2019-05-19 15:59:55 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  SYSTEM 2019-05-19 16:00:12 SYSTEM 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 SYSTEM 2019-05-19 16:00:43 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  SYSTEM 2019-05-19 16:01:01 SYSTEM 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 SYSTEM 2019-05-19 16:01:33 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Error SYSTEM 2019-05-19 16:01:50 SYSTEM CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  SYSTEM 2019-05-19 16:01:51 SYSTEM CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  SYSTEM 2019-05-19 16:03:26 SYSTEM CrowCam Controller - Done bouncing YouTube stream.
Error SYSTEM 2019-05-19 16:04:53 SYSTEM CrowCam Keep Alive - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1.
Error SYSTEM 2019-05-19 16:04:53 SYSTEM CrowCam Keep Alive - No final URL was obtained from /volume1/homes/admin/CrowCam/youtube-dl. Exiting program.
Error SYSTEM 2019-05-19 18:00:12 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  SYSTEM 2019-05-19 18:00:30 SYSTEM 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 SYSTEM 2019-05-19 18:01:03 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  SYSTEM 2019-05-19 18:01:23 SYSTEM 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 SYSTEM 2019-05-19 18:01:56 SYSTEM CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Error SYSTEM 2019-05-19 18:02:16 SYSTEM CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  SYSTEM 2019-05-19 18:02:17 SYSTEM CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  SYSTEM 2019-05-19 18:03:53 SYSTEM CrowCam Controller - Done bouncing YouTube stream.
Info  SYSTEM 2019-05-19 21:06:03 SYSTEM CrowCam Controller - We are after our sunset/stop time. YouTube Live Broadcast is up. It should be down at this time. Stopping stream.
Info  SYSTEM 2019-05-20 00:00:06 SYSTEM CrowCam Cleanup - 50 videos found. Processing.
Info  SYSTEM 2019-05-20 05:15:04 SYSTEM CrowCam Controller - We are after our sunrise/start time. YouTube Live Broadcast is down. It should be up at this time. Starting stream.
Error SYSTEM 2019-05-20 08:24:04 SYSTEM CrowCam Keep Alive - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1.
Error SYSTEM 2019-05-20 08:24:04 SYSTEM CrowCam Keep Alive - No final URL was obtained from /volume1/homes/admin/CrowCam/youtube-dl. Exiting program.
Error SYSTEM 2019-05-20 08:24:24 SYSTEM CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1, live stream is down.
Error SYSTEM 2019-05-20 08:24:24 SYSTEM CrowCam Controller - /volume1/homes/admin/CrowCam/youtube-dl returned an error message string, live stream is down.
Info  SYSTEM 2019-05-20 08:24:24 SYSTEM 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.
Info  SYSTEM 2019-05-20 08:25:12 SYSTEM CrowCam Controller - Live stream came back up.
Info  SYSTEM 2019-05-20 14:03:30 SYSTEM CrowCam Controller - Retrieving sunrise/sunset times from Google.
Info  SYSTEM 2019-05-20 14:03:32 SYSTEM CrowCam Controller - Retrieved sunrise/sunset times from Google: 5:25 AM/8:47 PM.

To do:

Detecing "videoIngestionFasterThanRealtime" has helped. Consider if the opposite error message "VideoIngestionStarved" should also be detected for.
I'm not sure what other errors I should be detecting for other than that. I don't see them all documented at YouTube API documentation, but there is some code examples here:
- https://github.com/google/google-api-objectivec-client-for-rest/blob/master/Source/GeneratedServices/YouTube/GTLRYouTubeObjects.h
- https://godoc.org/google.golang.org/api/youtube/v3

Added code to detect the "VideoIngestionStarved" state. For now it will just log if it detects that error.

To do:

Look at logs over time and see if VideoIngestionStarved comes up a lot, or if it comes up in the appropriate cases.
Decide if you want to de-nerf the code to actually bounce the stream if it detects the error.

https://www.youtube.com/watch?v=ngEd5ljc9b4 Video runs from 2019-05-22 6:01:43 pm to 8:27:24 pm (baked-in camera clock on the video stream), and the 8:27:24 was due to a failure bounce.

(The video started correctly at 6:01pm because that was when I first installed the midday-bounce code onto the production server and it correctly did a bounce as expected at that time.)

Logs show a bounce at 8:27:39 due to 3 repeats of "videoIngestionFasterThanRealtime" error starting at 8:26:35 pm.

Error 2019-05-22 20:26:35 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  2019-05-22 20:26:36 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-22 20:27:07 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Info  2019-05-22 20:27:07 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-22 20:27:39 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.
Error 2019-05-22 20:27:39 CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  2019-05-22 20:27:40 CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  2019-05-22 20:29:15 CrowCam Controller - Done bouncing YouTube stream.

Looking at the baked-in seconds counter on the video stream archive, I see that it counts the seconds just fine with no flaws during this entire time, all the way up to 8:27:24 pm. The bounce occurs at 8:27:39 pm, and it's a known thing that the video is delayed about 15 seconds, and 24+15=39 so it looks like the video feed was just fine all the way up to the last second.

The subsequent video clip plays up until EOD, from 8:29:17 9:06:11 pm, for a correct length of 36:53, with no problems and no log errors. The startup time of 8:29:17 corresponds very closely with the log entry which says it's starting the video around that time.

So I consider the "videoIngestionFasterThanRealtime" test to be flaky, tends to cry wolf, and should be adjusted. But how?

To do:

Consider increasing the number of hysteresis loops and also perhaps increase the delay between those hysteresis loops. See if doing this will weed out more of the flaky cry-wolf scenarios.

Do not:

Do not consider nerfing "videoIngestionFasterThanRealtime" and relying entirely on the other errors to bounce the stream if it has trouble. You already once had a situation where the stream was down all day with the spinny death icon. It happened shortly after you reinstated the API check with the austerity measures implemented. That one got a spinny death icon on the channel, but the other checks for $healthStatus and $streamStatus were just fine at that time because those checks were active when it happened.

I have checked in code that tries one additional hysteresis loop and extends the time length between each loop a bit. See if that addresses it? I'm not optimistic.

To do:

Look at logs over time and see if see if videoIngestionFasterThanRealtime continues to cry wolf.
Look at logs over time and see if VideoIngestionStarved comes up a lot, or if it comes up in the appropriate cases.
Decide if you want to de-nerf the code to actually bounce the stream if it detects the error.

Aha!

Looking back at day-before-yesterday's stream, the "videoIngestionFasterThanRealtime" check is indeed a good check. Here is an example of when it correctly solved a problem. It still might cry wolf sometimes, but this time, it wasn't a wolf cry, it was a genuine solve of the problem:

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.

So yeah, our check for videoIngestionFasterThanRealtime is provably good and needs to stay in place.

Remaining to do:

Look at logs over time and see if see if videoIngestionFasterThanRealtime continues to cry wolf sometimes, after our update to the hysteresis.
Look at logs over time and see if VideoIngestionStarved comes up a lot, or if it comes up in the appropriate cases.
Decide if you want to de-nerf the code to actually bounce the stream if it detects a VideoIngestionStarved error.

So far this morning there has been one non-repeating "blip" of the videoIngestionStarved message:

2019-05-23 05:10:03 CrowCam Controller - We are after our sunrise/start time. YouTube Live Broadcast is down. It should be up at this time. Starting stream.
2019-05-23 05:15:30 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.

That tells me a few things:

I got the text of the message correct. :)
There was an update of the Synology OS and Apps around 9am-ish, but that message was at 5am so it was unlikely related to the update.
It was more likely related to the sunrise startup of the video stream, a few minutes prior. The stream ingestion might indeed be briefly starved shortly after streamstart.
There is a 30-second pause in the code after the sunrise streamstart, so it gives it a little bit of time to spinup, but it seems that wasn't really enough? However, the hysteresis on the Test_Stream function should be fine enough to cover this.

Remaining to do:

Continue to look at logs over time and see if see if videoIngestionFasterThanRealtime continues to cry wolf sometimes, after our update to the hysteresis.
Continue to look at logs over time and see if VideoIngestionStarved comes up a lot, or if it comes up in the appropriate cases.
Decide if you want to de-nerf the code to actually bounce the stream if it detects a VideoIngestionStarved error.

I've gotten a couple of single blips of "videoIngestionStarved" (which were eaten up by the hysteresis), and they happened immediately after a stream startup or a stream bounce. I have increased the pausetime after these, to see if it makes the blip go away.

This video from 2019-05-25 shows a successful bounce and fix: https://www.youtube.com/watch?v=0jC2Yh1F1bA

The video on the YouTube site (previewed before processing was done) lasts until 5:47:06 pm and then ends. The YouTube API checks caught it and successfully bounced the stream. The errors which were caught and fixed were "inactive" and "noData".

Error 2019-05-25 17:50:07 CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error 2019-05-25 17:50:07 CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Info  2019-05-25 17:50:07 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 4 . Sleeping 40 seconds before trying again.
Error 2019-05-25 17:50:48 CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error 2019-05-25 17:50:48 CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Info  2019-05-25 17:50:48 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 4 . Sleeping 40 seconds before trying again.
Error 2019-05-25 17:51:30 CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error 2019-05-25 17:51:31 CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Info  2019-05-25 17:51:31 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 3 of 4 . Sleeping 40 seconds before trying again.
Error 2019-05-25 17:52:12 CrowCam Controller - The streamStatus is not active. Value retrieved was: inactive.
Error 2019-05-25 17:52:12 CrowCam Controller - The healthStatus is not good. Value retrieved was: noData.
Error 2019-05-25 17:52:12 CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.
Info  2019-05-25 17:52:17 CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.
Info  2019-05-25 17:54:03 CrowCam Controller - Done bouncing YouTube stream.

Remaining to do:

Continue to look at logs over time and see if see if videoIngestionFasterThanRealtime continues to cry wolf sometimes, after our update to the hysteresis.
Continue to look at logs over time and see if VideoIngestionStarved comes up a lot, or if it comes up in the appropriate cases.
See if you ever get a repeat of the spinny death icon which isn't fixed by the above code.
Eventually remove the currently-commented-out YouTube-DL code from CrowCam.sh.

Got more interesting data on 2019-05-27 about how the API checks are working!

The TLDR is:

I need to re-nerf "videoIngestionStarved" because it's crying wolf too much (done in the last commit).
"videoIngestionFasterThanRealtime" is working super great.
"streamStatus" and "healthStatus" continue to work great; Any time there is a problem with those, it usually indicates a problem with the stream too.
I have now observed what happens when the login to the YouTube API fails, and it appears to do the right thing: Failing the stream test and doing the necessary hysteresis backoff and then trying again. This worked in practice.

Full details of each of the events that occurred on 2019-05-27, showing the results:

https://www.youtube.com/watch?v=AyQpoMPtIos 2019-05-27 - Start 5:05 am - End 1:10 pm - Video length correct at 8:04:58 - Normal midday bounce with no video problems.

https://www.youtube.com/watch?v=KZilVm-rVUY 2019-05-27 - Start 1:12:39 pm - End 1:19:40 pm - Video length correct at 7:01 - Was bounced due to "videoIngestionStarved" message but there didn't seem to be anything visibly wrong with the video.

https://www.youtube.com/watch?v=kPM7tlhl9qg 2019-05-27 - Start 1:21:29 pm - End 1:29:20 pm - Video length correct at 7:52 - Was bounced due to "videoIngestionStarved" message but there didn't seem to be anything visibly wrong with the video.

https://www.youtube.com/watch?v=MFHTY5lFBRQ 2019-05-27 - Start 1:31:09 pm - End 1:39:10 pm - Video length is correct at 8:02 - Was bounced due to "videoIngestionStarved" message but there didn't seem to be anything visibly wrong with the video.

NOTE: Starting shortly before 6pm ish, there was noticeable network problems with The Agora internet. Certain web browsing things were working poorly. Vixy was trying to make holiday reservations on some web sites and the requests were timing out and being stuck. I think the bounces below are due to these valid network problems.

https://www.youtube.com/watch?v=I-YjaUcbEA0 2019-05-27 - Start 1:40:57 pm - Video length is wrong, end of video is messed up - At around 5:44:50 pm the video seems to freeze and then at 5:45 pm the video does the "speed up at the end" thing where the timestamps zoom by really fast and then the video ends. This is a valid bounce that detected the problem as "videoIngestionFasterThanRealtime" and repaired it. Initial detection was at 5:46 pm and the repair bounce correctly occurred at 5:49 pm.

https://www.youtube.com/watch?v=5ctLDEwlp7c 2019-05-27 - Start 5:50:52 pm - End 5:58:35 pm - Video length is correct at 7:39 - Was bounced due to "videoIngestionFasterThanRealtime" but there didn't seem to be anything visibly wrong with the video. Expectation: This was still a valid bounce because there were still network problems happening at this time, and the "videoIngestionFasterThanRealtime" message, though not reflected in the video itself, may have still been occurring due to this, and so I think the bounce is something that should have been done anyway.

https://www.youtube.com/watch?v=FrNiXFWTl9s 2019-05-27 - Start 6:00:37 pm - End 6:09:27 pm - Video length is wrong at 7:52 - Was bounced due to two reasons, "videoIngestionStarved" and because the access token, streamStatus, and healthStatus were all empty, due to a "Login Required" error. The bounce is valid, the video does the "speed up at the end" thing where the timestamps zoom by really fast and then the video ends. There appeared to be something bad happening to the network here, still, so that the API logins were failing just like Vixy's holiday reservations were failing. The output from the login attempt looked like this:

{ "error": { "errors": [ { "domain": "global", "reason": "required", "message": "Login Required", "locationType": "header", "location": "Authorization" } ], "code": 401, "message": "Login Required" } } .

I think that it's probably OK to re-nerf "videoIngestionStarved" and depend only on the "videoIngestionFasterThanRealtime", "streamStatus", and "healthStatus" errors for problem detection.

https://www.youtube.com/watch?v=HfRMJwGzrjo 2019-05-27 - Start 6:11:14 - End 9:10:03 pm - Video length is correct at 2:58:49 - Normal end of day stream shutdown.

Full log below:

Info   5/27/19 0:00   CrowCam Cleanup - 50 videos found. Processing.    
Info   5/27/19 0:00   CrowCam Cleanup - Title: CrowCam Id: jLAipmnPNnc Date: Tue May 21 18:21:34 PDT 2019 - more than 5 days old. Deleting CrowCam.    
Info   5/27/19 0:00   CrowCam Cleanup - Title: CrowCam Id: 8JXPZzO3wvo Date: Tue May 21 05:17:21 PDT 2019 - more than 5 days old. Deleting CrowCam.    
Info   5/27/19 5:05   CrowCam Controller - We are after our sunrise/start time. YouTube Live Broadcast is down. It should be up at this time. Starting stream.    
Info   5/27/19 13:10  CrowCam Controller - A midday stream bounce is needed, to prevent the current stream segment from exceeding the maximum video length.    
Info   5/27/19 13:10  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 13:11  CrowCam Controller - Done bouncing YouTube stream.    
Error  5/27/19 13:17  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:17  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:18  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:18  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:18  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:18  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:19  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Error  5/27/19 13:19  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 13:19  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 13:21  CrowCam Controller - Done bouncing YouTube stream.    
Error  5/27/19 13:27  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:27  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:27  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:27  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:28  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:28  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:29  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Error  5/27/19 13:29  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 13:29  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 13:31  CrowCam Controller - Done bouncing YouTube stream.    
Error  5/27/19 13:37  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:37  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:37  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:37  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:38  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 13:38  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 13:39  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Error  5/27/19 13:39  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 13:39  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 13:40  CrowCam Controller - Done bouncing YouTube stream.    
Info   5/27/19 14:02  CrowCam Controller - Retrieving sunrise/sunset times from Google.    
Info   5/27/19 14:02  CrowCam Controller - Retrieved sunrise/sunset times from Google: 5:18 AM/8:55 PM.    
Error  5/27/19 17:46  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:46  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:47  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:47  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:48  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:48  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:49  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Error  5/27/19 17:49  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 17:49  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 17:50  CrowCam Controller - Done bouncing YouTube stream.    
Error  5/27/19 17:56  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:56  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:57  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:57  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:58  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Info   5/27/19 17:58  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 17:58  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.    
Error  5/27/19 17:58  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 17:58  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 18:00  CrowCam Controller - Done bouncing YouTube stream.    
Error  5/27/19 18:06  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 18:06  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 18:07  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Info   5/27/19 18:07  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 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 18:08  CrowCam Controller - The variable accessToken came up empty. Error accessing YouTube API.    
Error  5/27/19 18:08  CrowCam Controller - The variable streamStatus came up empty. Error accessing YouTube API.    
Error  5/27/19 18:08  CrowCam Controller - The liveStreamsOutput was { "error": { "errors": [ { "domain": "global", "reason": "required", "message": "Login Required", "locationType": "header", "location": "Authorization" } ], "code": 401, "message": "Login Required" } } .    
Error  5/27/19 18:08  CrowCam Controller - The variable healthStatus came up empty. Error accessing YouTube API.    
Error  5/27/19 18:08  CrowCam Controller - The liveStreamsOutput was { "error": { "errors": [ { "domain": "global", "reason": "required", "message": "Login Required", "locationType": "header", "location": "Authorization" } ], "code": 401, "message": "Login Required" } } .    
Info   5/27/19 18:08  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 3 of 4 . Sleeping 40 seconds before trying again.    
Error  5/27/19 18:09  CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionStarved.    
Error  5/27/19 18:09  CrowCam Controller - Bouncing the YouTube stream, because it was unexpectedly down.    
Info   5/27/19 18:09  CrowCam Controller - Pausing, after bringing down the stream, before bringing it up again.    
Info   5/27/19 18:11  CrowCam Controller - Done bouncing YouTube stream.    
Info   5/27/19 21:10  CrowCam Controller - We are after our sunset/stop time. YouTube Live Broadcast is up. It should be down at this time. Stopping stream.    
Info   5/28/19 0:00   CrowCam Cleanup - 50 videos found. Processing.    
Info   5/28/19 0:00   CrowCam Cleanup - Title: CrowCam Id: 1LmycDEBUHM Date: Wed May 22 20:28:49 PDT 2019 - more than 5 days old. Deleting CrowCam.    
Info   5/28/19 0:00   CrowCam Cleanup - Title: CrowCam Id: ngEd5ljc9b4 Date: Wed May 22 18:01:14 PDT 2019 - more than 5 days old. Deleting CrowCam.    
Info   5/28/19 5:05   CrowCam Controller - We are after our sunrise/start time. YouTube Live Broadcast is down. It should be up at this time. Starting stream.

This has been doing very well the last several days. Closing bug.

tfabris / CrowCam

Live feed hangs and gets "reload" icon sometimes. #23