Bump version: 0.4.0 → 0.5.0

Unifi protect does not return full video clips if the clip is requested too soon.
There are two issues at play here:
  - Protect will only cut a clip on an keyframe which happen every 5s
  - Protect's pipeline needs a finite amount of time to make a clip available

Known Issues: It still seems to sometimes miss a single frame

.bumpversion.cfg

@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 0.4.0
+current_version = 0.5.0
 commit = True
 tag = True
 

CHANGELOG.md

@@ -4,7 +4,14 @@ All notable changes to this project will be documented in this file.
 The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
 and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 
-## [0.4.0] - 2022-02-24
+## [0.5.0] - 2022-03-06
+### Added
+- If `ffprobe` is available, the downloaded clips length is checked and logged
+### Fixed
+- A time delay has been added before downloading clips to try to resolve an issue where
+  downloaded clips were too short
+
+## [0.4.0] - 2022-03-05
 ### Added
 - A `--version` command line option to show the tools version
 ### Fixed

Dockerfile

@@ -4,8 +4,8 @@
 FROM python:3.9-alpine
 
 WORKDIR /app
-RUN apk add gcc musl-dev zlib-dev jpeg-dev rclone
-COPY dist/unifi-protect-backup-0.4.0.tar.gz sdist.tar.gz
+RUN apk add gcc musl-dev zlib-dev jpeg-dev rclone ffmpeg
+COPY dist/unifi-protect-backup-0.5.0.tar.gz sdist.tar.gz
 RUN pip install sdist.tar.gz
 
 ENV UFP_USERNAME=unifi_protect_user

README.md

@@ -36,6 +36,7 @@ retention period.
 1. Install `rclone`. Instructions for your platform can be found here: https://rclone.org/install/#quickstart
 2. Configure the `rclone` remote you want to backup to. Instructions can be found here: https://rclone.org/docs/#configure
 3. `pip install unifi-protect-backup`
+4. Optional: Install `ffprobe` so that `unifi-protect-backup` can check the length of the clips it downloads
 
 ## Usage
 

pyproject.toml

@@ -1,7 +1,7 @@
 [tool]
 [tool.poetry]
 name = "unifi-protect-backup"
-version = "0.4.0"
+version = "0.5.0"
 homepage = "https://github.com/ep1cman/unifi-protect-backup"
 description = "Python tool to backup unifi event clips in realtime."
 authors = ["sebastian.goscik <sebastian@goscik.com>"]

unifi_protect_backup/__init__.py

@@ -2,6 +2,6 @@
 
 __author__ = """sebastian.goscik"""
 __email__ = 'sebastian@goscik.com'
-__version__ = '0.4.0'
+__version__ = '0.5.0'
 
 from .unifi_protect_backup import UnifiProtectBackup

unifi_protect_backup/unifi_protect_backup.py

@@ -1,8 +1,10 @@
 """Main module."""
 import asyncio
+from datetime import datetime, timedelta, timezone
 import logging
 import pathlib
 import shutil
+import json
 from asyncio.exceptions import TimeoutError
 from typing import Callable, List, Optional
 
@@ -16,7 +18,7 @@ from pyunifiprotect.data.websocket import WSAction, WSSubscriptionMessage
 logger = logging.getLogger(__name__)
 
 
-class RcloneException(Exception):
+class SubprocessException(Exception):
     """Exception class for when rclone does not exit with `0`."""
 
     def __init__(self, stdout, stderr, returncode):
@@ -174,6 +176,7 @@ class UnifiProtectBackup:
         verbose (int): How verbose to setup logging, see :func:`setup_logging` for details.
         _download_queue (asyncio.Queue): Queue of events that need to be backed up
         _unsub (Callable): Unsubscribe from the websocket callback
+        _has_ffprobe (bool): If ffprobe was found on the host
     """
 
     def __init__(
@@ -248,6 +251,8 @@ class UnifiProtectBackup:
         self._download_queue: asyncio.Queue = asyncio.Queue()
         self._unsub: Callable[[], None]
 
+        self._has_ffprobe = False
+
     async def start(self):
         """Bootstrap the backup process and kick off the main loop.
 
@@ -256,10 +261,16 @@ class UnifiProtectBackup:
         """
         logger.info("Starting...")
 
-        # Ensure rclone is installed and properly configured
+        # Ensure `rclone` is installed and properly configured
         logger.info("Checking rclone configuration...")
         await self._check_rclone()
 
+        # Check if `ffprobe` is available
+        ffprobe = shutil.which('ffprobe')
+        if ffprobe is not None:
+            logger.debug(f"ffprobe found: {ffprobe}")
+            self._has_ffprobe = True
+
         # Start the pyunifiprotect connection by calling `update`
         logger.info("Connecting to Unifi Protect...")
         await self._protect.update()
@@ -361,14 +372,14 @@ class UnifiProtectBackup:
         """Check if rclone is installed and the specified remote is configured.
 
         Raises:
-            RcloneException: If rclone is not installed or it failed to list remotes
+            SubprocessException: If rclone is not installed or it failed to list remotes
             ValueError: The given rclone destination is for a remote that is not configured
 
         """
         rclone = shutil.which('rclone')
-        logger.debug(f"rclone found: {rclone}")
         if not rclone:
             raise RuntimeError("`rclone` is not installed on this system")
+        logger.debug(f"rclone found: {rclone}")
 
         cmd = "rclone listremotes -vv"
         proc = await asyncio.create_subprocess_shell(
@@ -380,7 +391,7 @@ class UnifiProtectBackup:
         logger.extra_debug(f"stdout:\n{stdout.decode()}")  # type: ignore
         logger.extra_debug(f"stderr:\n{stderr.decode()}")  # type: ignore
         if proc.returncode != 0:
-            raise RcloneException(stdout.decode(), stderr.decode(), proc.returncode)
+            raise SubprocessException(stdout.decode(), stderr.decode(), proc.returncode)
 
         # Check if the destination is for a configured remote
         for line in stdout.splitlines():
@@ -429,9 +440,23 @@ class UnifiProtectBackup:
                 logger.debug(f"Remaining Queue: {self._download_queue.qsize()}")
                 logger.debug(f"  Camera: {await self._get_camera_name(event.camera_id)}")
                 logger.debug(f"  Type: {event.type}")
-                logger.debug(f"  Start: {event.start.strftime('%Y-%m-%dT%H-%M-%S')}")
-                logger.debug(f"  End: {event.end.strftime('%Y-%m-%dT%H-%M-%S')}")
-                logger.debug(f"  Duration: {event.end-event.start}")
+                logger.debug(f"  Start: {event.start.strftime('%Y-%m-%dT%H-%M-%S')} ({event.start.timestamp()})")
+                logger.debug(f"  End: {event.end.strftime('%Y-%m-%dT%H-%M-%S')} ({event.end.timestamp()})")
+                duration = (event.end - event.start).total_seconds()
+                logger.debug(f"  Duration: {duration}")
+
+                # Unifi protect does not return full video clips if the clip is requested too soon.
+                # There are two issues at play here:
+                #  - Protect will only cut a clip on an keyframe which happen every 5s
+                #  - Protect's pipeline needs a finite amount of time to make a clip available
+                # So we will wait 1.5x the keyframe interval to ensure that there is always ample video
+                # stored and Protect can return a full clip (which should be at least the length requested,
+                # but often longer)
+                time_since_event_ended = datetime.utcnow().replace(tzinfo=timezone.utc) - event.end
+                sleep_time = (timedelta(seconds=5 * 1.5) - time_since_event_ended).total_seconds()
+                if sleep_time > 0:
+                    logger.debug(f"  Sleeping ({sleep_time}s) to ensure clip is ready to download...")
+                    await asyncio.sleep(sleep_time)
 
                 # Download video
                 logger.debug("  Downloading video...")
@@ -450,6 +475,21 @@ class UnifiProtectBackup:
 
                 destination = await self.generate_file_path(event)
 
+                # Get the actual length of the downloaded video using ffprobe
+                if self._has_ffprobe:
+                    try:
+                        downloaded_duration = await self._get_video_length(video)
+                        msg = f"  Downloaded video length: {downloaded_duration:.3f}s" \
+                              f"({downloaded_duration - duration:+.3f}s)"
+                        if downloaded_duration < duration:
+                            logger.warning(msg)
+                        else:
+                            logger.debug(msg)
+                    except SubprocessException as e:
+                        logger.warn(f"    `ffprobe` failed")
+                        logger.exception(e)
+
+                # Upload video
                 logger.debug("  Uploading video via rclone...")
                 logger.debug(f"    To: {destination}")
                 logger.debug(f"    Size: {human_readable_size(len(video))}")
@@ -457,7 +497,7 @@ class UnifiProtectBackup:
                     try:
                         await self._upload_video(video, destination, self.rclone_args)
                         break
-                    except RcloneException as e:
+                    except SubprocessException as e:
                         logger.warn(f"    Failed upload attempt {x+1}, retying in 1s")
                         logger.exception(e)
                         await asyncio.sleep(1)
@@ -497,7 +537,26 @@ class UnifiProtectBackup:
             logger.extra_debug(f"stdout:\n{stdout.decode()}")  # type: ignore
             logger.extra_debug(f"stderr:\n{stderr.decode()}")  # type: ignore
         else:
-            raise RcloneException(stdout.decode(), stderr.decode(), proc.returncode)
+            raise SubprocessException(stdout.decode(), stderr.decode(), proc.returncode)
+
+    async def _get_video_length(self, video: bytes) -> float:
+        cmd = 'ffprobe -v quiet -show_streams -select_streams v:0 -of json -'
+        proc = await asyncio.create_subprocess_shell(
+            cmd,
+            stdin=asyncio.subprocess.PIPE,
+            stdout=asyncio.subprocess.PIPE,
+            stderr=asyncio.subprocess.PIPE,
+        )
+        stdout, stderr = await proc.communicate(video)
+        if proc.returncode == 0:
+            logger.extra_debug(f"stdout:\n{stdout.decode()}")  # type: ignore
+            logger.extra_debug(f"stderr:\n{stderr.decode()}")  # type: ignore
+
+            json_data = json.loads(stdout.decode())
+            return float(json_data['streams'][0]['duration'])
+
+        else:
+            raise SubprocessException(stdout.decode(), stderr.decode(), proc.returncode)
 
     async def generate_file_path(self, event: Event) -> pathlib.Path:
         """Generates the rclone destination path for the provided event.