Deleted Video appears in custom playlist.

[tfabris]

Occasionally an entry in the custom playlist "CrowCam Archives" appears. The entry is titled "Deleted video" and its description is "This video is unavailable."

At first, I thought it was the CrowCam Cleanup feature which was deleting old videos without cleaning them up out of the playlist. However I added code for CrowCam Cleanup to also delete the video's playlist entry, and that code is correctly running, and the "problem" entry does not correspond to this, I don't think. So in theory that cleanup should be working to also delete the playlist entries at those times.

I need to find out what makes these "Deleted video" entries show up and address the root cause.

The one I'm looking at, where I noticed it, appears in an odd place. I have in my list, in this reverse chronological order:

• Wed, Nov 27, 2019 - 12pm-4pm
• Wed, Nov 27, 2019 - 7am-12pm
• (zero date - unix epoch) - Deleted video - Note: Video ID was hKmQyeInJsM
• Tue, Nov 26, 2019 - 12pm-4pm
• Tue, Nov 26, 2019 - 7am-12pm

Important takeaways from the list above: Since I noticed this list issue on 2019-09-29, this wasn't a video being cleaned up at that slot in the time stream. The video dates are only 2-3 days in the past, and my cleanup value is set to 9 at the time. So it's not a cleanup occurring. Also the videos surrounding it were just "CrowCam" and it didn't clean those up. Also the videos surrounding it are all sequential and correct, so this "Deleted video" is an insertion of some kind. It's not supposed to be in that location in the playlist. How did it get there?

The playlist entry for this video in the JSON looks like this:

      { 
         "kind":"youtube#playlistItem",
         "etag":"\"j6xRRd8dTPVVptg711_CSPADRfg/zAt8TVNBOsk4TVLtP_RjP5J44WE\"",
         "id":"UExxaS1McjFoUEJPVXVCZ012c0RNWTJLM2lVZzZuQlpBVi5DM0UwMkNDRTIwQUNDMjE2",
         "snippet":{ 
            "publishedAt":"2019-11-27T00:42:12.000Z",
            "channelId":"UCqPZGFtBau8rm7wnScxdA3g",
            "title":"Deleted video",
            "description":"This video is unavailable.",
            "channelTitle":"Vixy & Tony",
            "playlistId":"PLqi-Lr1hPBOUuBgMvsDMY2K3iUg6nBZAV",
            "position":5,
            "resourceId":{ 
               "kind":"youtube#video",
               "videoId":"hKmQyeInJsM"
            }
         }
      },

Theories to check:

• Maybe because I delete the video first and the playlist entry second, maybe that is what causes this to occur? Consider changing the code to delete the playlist entry first.
• Maybe there is some situation where creation of a new video on a daily basis is causing these orphaned playlist entries. If so, it's not my fault, since that part of it is all YouTube.
• Maybe there is a problem with moments where there is network trouble or video stream bouncing/splitting trouble that is causing this to occur. The timing of the playlist entry appears to correspond with the End Of Day of the prior video in the playlist.

To do:

• See if any more of these appear of the next several days while you're in Germany. If so, note their video IDs.
• Change the code to delete the playlist entry first.
• See if the synology logs, the ones which show that an item is being cleaned up, see if their timing corresponds with the appearance of this "deleted item" in the playlist, and if the video ID corresponds to hKmQyeInJsM.
• See if the publishedAt timestamp for the playlist item corresponds to anything in the Synology log. It was "publishedAt":"2019-11-27T00:42:12.000Z", which is 2019-11-26 16:42:12 pacific time. This is curious because the prior video in the list has (what appears on the archival video to be) a clean End of Day which is 16:41:00, 72 seconds prior to that timestamp.
• See if in the synology logs if you can see whether the timing of this observed item corresponds with a network problem or a stream bounce or something.
• Depending on what you find out above, consider simply writing additional cleanup code to scrub playlist items with the title "Deleted video".

[tfabris]

Done:

• Didn't see any recurrences besides the one reported in the initial bug report.
• Checked in changes which should hopefully deal with this and simply clean up the mess, regardless of the root cause.

To do:

• Before putting into production, investigate all the stuff in the previous comment. This code, if it works, will clean up the issue, potentially erasing the forensics, so do your investigation first.
• Test this in production by running it on the Synology from the console without debug mode. There's a deleted video sitting in the list right now which will get cleaned up, so watch it work real time to ensure the happy path is functioning.

[tfabris]

Investigation results:

• Searching the Synology log, I see no entries containing the video ID of hKmQyeInJsM at any time within its searchable history.
• Log entries showed a normal end-of-day shutdown at the approximate time of the "publishedAt" value of the problematic video. It was "publishedAt":"2019-11-27T00:42:12.000Z", which is 2019-11-26 16:42:12. The logs show a normal end-of-day shutdown at 16:42:18.
• I see minor network problems shortly before and shortly after the time in question. One is a series of videoIngestionFasterThanRealtime's in the time period before the end of day shutdown, and another is a failure to download the latest YouTube-DL at 16:42:44.
• Relevant log entries for that time period:

2019-11-28 00:04:27 CrowCam Cleanup - 216 playlistItemIds, 216 videoIds, 216 titles found. Processing.
2019-11-27 16:42:44 CrowCam Keep Alive - No final URL was obtained from /volume1/homes/admin/CrowCam/youtube-dl. Exiting program.
2019-11-27 16:42:43 CrowCam Keep Alive - /volume1/homes/admin/CrowCam/youtube-dl finished with exit code 1.
2019-11-27 16:42:18 CrowCam Controller - We are after our sunset/stop time. YouTube Live Broadcast is up. It should be down at this time. Stopping stream.
2019-11-27 16:18:14 CrowCam Controller - Done bouncing YouTube stream.
2019-11-27 16:18:09 CrowCam Controller - Bouncing stream for 4 seconds.
2019-11-27 16:18:09 CrowCam Controller - Bouncing the YouTube stream for 4 seconds, because the stream was unexpectedly down.
2019-11-27 16:18:09 CrowCam Controller - The configurationIssues contains a bad value. Value retrieved was: videoIngestionFasterThanRealtime.

Investigation conclusion: Comcast bullshit.

OK to implement final version of code in production, which should close this issue if it works.

[tfabris]

Auto-cleanup seems to be working correctly in production.

Note: When a Deleted File is cleaned up, it will still appear in the crowcam-videodata for that particular run, since the cleanup step happens after the videodata was retrieved. But it will be scrubbed on the next automatic run of CrowCamCleanup.sh. This is OK for my purposes.

Closing bug.