Bump version: 0.5.0 → 0.5.1

' does not work as expected in windows

.bumpversion.cfg

@@ -1,5 +1,5 @@
 [bumpversion]
-current_version = 0.2.1
+current_version = 0.5.1
 commit = True
 tag = True
 

.github/workflows/dev.yml

@@ -55,6 +55,7 @@ jobs:
   dev_container:
     name: Create dev container
     runs-on: ubuntu-20.04
+    if: github.event_name != 'pull_request'
     strategy:
       matrix:
         python-versions: [3.9]

CHANGELOG.md

@@ -4,6 +4,36 @@ 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.5.1] - 2022-03-07
+### Fixed
+- rclone command now works as expected on windows when spaces are in the file path
+
+## [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
+- Websocket checks are no longer logged in verbosity level 1 to reduce log spam
+
+## [0.3.1] - 2022-02-24
+### Fixed
+- Now checks if the websocket connection is alive, and attempts to reconnect if it isn't.
+
+## [0.3.0] - 2022-02-22
+### Added
+- New CLI argument for passing CLI arguments directly to `rclone`.
+
+### Fixed
+- A new camera getting added while running no longer crashes the application.
+- A timeout during download now correctly retries the download instead of
+  abandoning the event.
+
 ## [0.2.1] - 2022-02-21
 ### Fixed
 - Retry logging formatting

CONTRIBUTING.md

@@ -59,7 +59,8 @@ Ready to contribute? Here's how to set up `unifi-protect-backup` for local devel
 4. Install dependencies and start your virtualenv:
 
     ```
-    $ poetry install -E test -E doc -E dev
+    $ poetry install -E test -E dev
+    $ poetry shell
     ```
 
 5. Create a branch for local development:
@@ -70,14 +71,21 @@ Ready to contribute? Here's how to set up `unifi-protect-backup` for local devel
 
     Now you can make your changes locally.
 
-6. When you're done making changes, check that your changes pass the
+6. To run `unifi-protect-backup` while developing you will need to either
+   be inside the `poetry shell` virtualenv or run it via poetry:
+
+   ```
+   $ poetry run unifi-protect-backup {args}
+   ```
+
+7. When you're done making changes, check that your changes pass the
    tests, including testing other Python versions, with tox:
 
     ```
     $ poetry run tox
     ```
 
-7. Commit your changes and push your branch to GitHub:
+8. Commit your changes and push your branch to GitHub:
 
     ```
     $ git add .
@@ -85,7 +93,7 @@ Ready to contribute? Here's how to set up `unifi-protect-backup` for local devel
     $ git push origin name-of-your-bugfix-or-feature
     ```
 
-8. Submit a pull request through the GitHub website.
+9. Submit a pull request through the GitHub website.
 
 ## Pull Request Guidelines
 
@@ -93,8 +101,8 @@ Before you submit a pull request, check that it meets these guidelines:
 
 1. The pull request should include tests.
 2. If the pull request adds functionality, the docs should be updated. Put
-   your new functionality into a function with a docstring, and add the
-   feature to the list in README.md.
+   your new functionality into a function with a docstring. If adding a CLI
+   option, you should update the "usage" in README.md.
 3. The pull request should work for Python 3.9. Check
    https://github.com/ep1cman/unifi-protect-backup/actions
    and make sure that the tests pass for all supported Python versions.
@@ -120,4 +128,5 @@ $ git push
 $ git push --tags
 ```
 
-GitHub Actions will then deploy to PyPI if tests pass.
+GitHub Actions will then deploy to PyPI, produce a GitHub release, and a container
+build if tests pass.

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.2.1.tar.gz sdist.tar.gz
+RUN apk add gcc musl-dev zlib-dev jpeg-dev rclone ffmpeg
+COPY dist/unifi-protect-backup-0.5.1.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
 
@@ -64,6 +65,15 @@ Options:
                                   of `rclone`
                                   (https://rclone.org/filtering/#max-age-don-
                                   t-transfer-any-file-older-than-this)
+  --rclone-args TEXT              Optional arguments which are directly passed
+                                  to `rclone rcat`. These can by used to set
+                                  parameters such as the bandwidth limit used
+                                  when pushing the files to the rclone
+                                  destination, e.g., '--bwlimit=500k'. Please
+                                  see the `rclone` documentation for the full
+                                  set of arguments it supports
+                                  (https://rclone.org/docs/). Please use
+                                  responsibly.
   --ignore-camera TEXT            IDs of cameras for which events should not
                                   be backed up. Use multiple times to ignore
                                   multiple IDs. If being set as an environment
@@ -106,6 +116,7 @@ always take priority over environment variables):
 - `UFP_SSL_VERIFY`
 - `RCLONE_RETENTION`
 - `RCLONE_DESTINATION`
+- `RCLONE_ARGS`
 - `IGNORE_CAMERAS`
 
 ## Docker Container

pyproject.toml

@@ -1,7 +1,7 @@
 [tool]
 [tool.poetry]
 name = "unifi-protect-backup"
-version = "0.2.1"
+version = "0.5.1"
 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.2.1'
+__version__ = '0.5.1'
 
 from .unifi_protect_backup import UnifiProtectBackup

unifi_protect_backup/cli.py

@@ -4,10 +4,11 @@ import asyncio
 
 import click
 
-from unifi_protect_backup import UnifiProtectBackup
+from unifi_protect_backup import UnifiProtectBackup, __version__
 
 
 @click.command()
+@click.version_option(__version__)
 @click.option('--address', required=True, envvar='UFP_ADDRESS', help='Address of Unifi Protect instance')
 @click.option('--port', default=443, envvar='UFP_PORT', help='Port of Unifi Protect instance')
 @click.option('--username', required=True, envvar='UFP_USERNAME', help='Username to login to Unifi Protect instance')
@@ -32,6 +33,13 @@ from unifi_protect_backup import UnifiProtectBackup
     help="How long should event clips be backed up for. Format as per the `--max-age` argument of "
     "`rclone` (https://rclone.org/filtering/#max-age-don-t-transfer-any-file-older-than-this)",
 )
+@click.option(
+    '--rclone-args',
+    default='',
+    envvar='RCLONE_ARGS',
+    help="Optional extra arguments to pass to `rclone rcat` directly. Common usage for this would "
+    "be to set a bandwidth limit, for example.",
+)
 @click.option(
     '--ignore-camera',
     'ignore_cameras',

unifi_protect_backup/unifi_protect_backup.py

@@ -1,13 +1,16 @@
 """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
 
 import aiocron
-import aiohttp
-from pyunifiprotect import ProtectApiClient
+from aiohttp.client_exceptions import ClientPayloadError
+from pyunifiprotect import NvrError, ProtectApiClient
 from pyunifiprotect.data.nvr import Event
 from pyunifiprotect.data.types import EventType, ModelType
 from pyunifiprotect.data.websocket import WSAction, WSSubscriptionMessage
@@ -15,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):
@@ -168,10 +171,12 @@ class UnifiProtectBackup:
         retention (str): How long should event clips be backed up for. Format as per the
                          `--max-age` argument of `rclone`
                          (https://rclone.org/filtering/#max-age-don-t-transfer-any-file-older-than-this)
+        rclone_args (str): Extra args passed directly to `rclone rcat`.
         ignore_cameras (List[str]): List of camera IDs for which to not backup events
         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__(
@@ -182,6 +187,7 @@ class UnifiProtectBackup:
         verify_ssl: bool,
         rclone_destination: str,
         retention: str,
+        rclone_args: str,
         ignore_cameras: List[str],
         verbose: int,
         port: int = 443,
@@ -200,6 +206,8 @@ class UnifiProtectBackup:
             retention (str): How long should event clips be backed up for. Format as per the
                             `--max-age` argument of `rclone`
                             (https://rclone.org/filtering/#max-age-don-t-transfer-any-file-older-than-this)
+            rclone_args (str): A bandwidth limit which is passed to the `--bwlimit` argument of
+                                   `rclone` (https://rclone.org/docs/#bwlimit-bandwidth-spec)
             ignore_cameras (List[str]): List of camera IDs for which to not backup events
             verbose (int): How verbose to setup logging, see :func:`setup_logging` for details.
         """
@@ -217,24 +225,34 @@ class UnifiProtectBackup:
         logger.debug(f"  {verify_ssl=}")
         logger.debug(f"  {rclone_destination=}")
         logger.debug(f"  {retention=}")
+        logger.debug(f"  {rclone_args=}")
         logger.debug(f"  {ignore_cameras=}")
         logger.debug(f"  {verbose=}")
 
         self.rclone_destination = rclone_destination
         self.retention = retention
+        self.rclone_args = rclone_args
+
+        self.address = address
+        self.port = port
+        self.username = username
+        self.password = password
+        self.verify_ssl = verify_ssl
 
         self._protect = ProtectApiClient(
-            address,
-            port,
-            username,
-            password,
-            verify_ssl=verify_ssl,
+            self.address,
+            self.port,
+            self.username,
+            self.password,
+            verify_ssl=self.verify_ssl,
             subscribed_models={ModelType.EVENT},
         )
         self.ignore_cameras = ignore_cameras
         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.
 
@@ -243,13 +261,21 @@ 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()
+
+        # Get a mapping of camera ids -> names
         logger.info("Found cameras:")
         for camera in self._protect.bootstrap.cameras.values():
             logger.info(f" - {camera.id}: {camera.name}")
@@ -272,14 +298,67 @@ class UnifiProtectBackup:
             )
             stdout, stderr = await proc.communicate()
             if proc.returncode == 0:
-                logger.extra_debug(f"stdout:\n{stdout.decode()}")  # type: ignore
-                logger.extra_debug(f"stderr:\n{stderr.decode()}")  # type: ignore
+                logger.extra_debug(f"stdout:\n{stdout.decode()}")
+                logger.extra_debug(f"stderr:\n{stderr.decode()}")
                 logger.info("Successfully deleted old files")
             else:
                 logger.warn("Failed to purge old files")
                 logger.warn(f"stdout:\n{stdout.decode()}")
                 logger.warn(f"stderr:\n{stderr.decode()}")
 
+        # We need to catch websocket disconnect and trigger a reconnect.
+        @aiocron.crontab("* * * * *")
+        async def check_websocket_and_reconnect():
+            logger.extra_debug("Checking the status of the websocket...")
+            if self._protect.check_ws():
+                logger.extra_debug("Websocket is connected.")
+            else:
+                logger.warn("Lost connection to Unifi Protect.")
+
+                # Unsubscribe, close the session.
+                self._unsub()
+                await self._protect.close_session()
+
+                while True:
+                    logger.warn("Attempting reconnect...")
+
+                    try:
+                        # Start again from scratch. In principle if Unifi
+                        # Protect has not been restarted we should just be able
+                        # to call self._protect.update() to reconnect to the
+                        # websocket. However, if the server has been restarted a
+                        # call to self._protect.check_ws() returns true and some
+                        # seconds later pyunifiprotect detects the websocket as
+                        # disconnected again. Therefore, kill it all and try
+                        # again!
+                        replacement_protect = ProtectApiClient(
+                            self.address,
+                            self.port,
+                            self.username,
+                            self.password,
+                            verify_ssl=self.verify_ssl,
+                            subscribed_models={ModelType.EVENT},
+                        )
+                        # Start the pyunifiprotect connection by calling `update`
+                        await replacement_protect.update()
+                        if replacement_protect.check_ws():
+                            self._protect = replacement_protect
+                            self._unsub = self._protect.subscribe_websocket(self._websocket_callback)
+                            break
+                        else:
+                            logger.warn("Unable to establish connection to Unifi Protect")
+                    except Exception as e:
+                        logger.warn("Unexpected exception occurred while trying to reconnect:")
+                        logger.exception(e)
+                    finally:
+                        # If we get here we need to close the replacement session again
+                        await replacement_protect.close_session()
+
+                        # Back off for a little while
+                        await asyncio.sleep(10)
+
+                logger.info("Re-established connection to Unifi Protect and to the websocket.")
+
         # Launches the main loop
         logger.info("Listening for events...")
         await self._backup_events()
@@ -293,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(
@@ -312,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():
@@ -354,18 +433,31 @@ class UnifiProtectBackup:
 
         """
         while True:
-            event = await self._download_queue.get()
-            destination = self.generate_file_path(event)
-
-            logger.info(f"Backing up event: {event.id}")
-            logger.debug(f"Remaining Queue: {self._download_queue.qsize()}")
-            logger.debug(f"  Camera: {self._protect.bootstrap.cameras[event.camera_id].name}")
-            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}")
-
             try:
+                event = await self._download_queue.get()
+
+                logger.info(f"Backing up event: {event.id}")
+                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')} ({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...")
                 for x in range(5):
@@ -373,7 +465,7 @@ class UnifiProtectBackup:
                         video = await self._protect.get_camera_video(event.camera_id, event.start, event.end)
                         assert isinstance(video, bytes)
                         break
-                    except (AssertionError, aiohttp.client_exceptions.ClientPayloadError) as e:
+                    except (AssertionError, ClientPayloadError, TimeoutError) as e:
                         logger.warn(f"    Failed download attempt {x+1}, retying in 1s")
                         logger.exception(e)
                         await asyncio.sleep(1)
@@ -381,14 +473,31 @@ class UnifiProtectBackup:
                     logger.warn(f"Download failed after 5 attempts, abandoning event {event.id}:")
                     continue
 
+                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("    `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))}")
                 for x in range(5):
                     try:
-                        await self._upload_video(video, destination)
+                        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)
@@ -402,7 +511,7 @@ class UnifiProtectBackup:
                 logger.warn(f"Unexpected exception occurred, abandoning event {event.id}:")
                 logger.exception(e)
 
-    async def _upload_video(self, video: bytes, destination: pathlib.Path):
+    async def _upload_video(self, video: bytes, destination: pathlib.Path, rclone_args: str):
         """Upload video using rclone.
 
         In order to avoid writing to disk, the video file data is piped directly
@@ -411,11 +520,12 @@ class UnifiProtectBackup:
         Args:
             video (bytes): The data to be written to the file
             destination (pathlib.Path): Where rclone should write the file
+            rclone_args (str): Optional extra arguments to pass to `rclone`
 
         Raises:
             RuntimeError: If rclone returns a non-zero exit code
         """
-        cmd = f"rclone rcat -vv '{destination}'"
+        cmd = f'rclone rcat -vv {rclone_args} "{destination}"'
         proc = await asyncio.create_subprocess_shell(
             cmd,
             stdin=asyncio.subprocess.PIPE,
@@ -427,9 +537,28 @@ 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)
 
-    def generate_file_path(self, event: Event) -> pathlib.Path:
+    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.
 
         Generates paths in the following structure:
@@ -448,7 +577,7 @@ class UnifiProtectBackup:
         """
         path = pathlib.Path(self.rclone_destination)
         assert isinstance(event.camera_id, str)
-        path /= self._protect.bootstrap.cameras[event.camera_id].name  # directory per camera
+        path /= await self._get_camera_name(event.camera_id)  # directory per camera
         path /= event.start.strftime("%Y-%m-%d")  # Directory per day
 
         file_name = f"{event.start.strftime('%Y-%m-%dT%H-%M-%S')} {event.type}"
@@ -461,3 +590,20 @@ class UnifiProtectBackup:
         path /= file_name
 
         return path
+
+    async def _get_camera_name(self, id: str):
+        try:
+            return self._protect.bootstrap.cameras[id].name
+        except KeyError:
+            # Refresh cameras
+            logger.debug(f"Unknown camera id: '{id}', checking API")
+
+            try:
+                await self._protect.update(force=True)
+            except NvrError:
+                logger.debug(f"Unknown camera id: '{id}'")
+                raise
+
+            name = self._protect.bootstrap.cameras[id].name
+            logger.debug(f"Found camera - {id}: {name}")
+            return name