diff --git a/unifi_protect_backup/unifi_protect_backup.py b/unifi_protect_backup/unifi_protect_backup.py index 36060bd..d3313c7 100644 --- a/unifi_protect_backup/unifi_protect_backup.py +++ b/unifi_protect_backup/unifi_protect_backup.py @@ -64,38 +64,70 @@ def addLoggingLevel(levelName, levelNum, methodName=None): setattr(logging, methodName, logToRoot) -def setup_logging(verbosity): - logging.basicConfig(level=logging.INFO) - addLoggingLevel( - 'WEBSOCKET_DUMP', - logging.DEBUG - 5, +def setup_logging(verbosity: int) -> None: + """Configures loggers to provided the desired level of verbosity + + Verbosity 0: Only log info messages created by `unifi-protect-backup`, and all warnings + verbosity 1: Only log info & debug messages created by `unifi-protect-backup`, and all warnings + verbosity 2: Log info & debug messages created by `unifi-protect-backup`, command output, and + all warnings + Verbosity 3: Log debug messages created by `unifi-protect-backup`, command output, all info + messages, and all warnings + Verbosity 4: Log debug messages created by `unifi-protect-backup` command output, all info + messages, all warnings, and websocket data + Verbosity 5: Log websocket data, command output, all debug messages, all info messages and all + warnings + + Args: + verbosity (int): The desired level of verbosity + + """ + add_logging_level( + 'EXTRA_DEBUG', + logging.DEBUG - 1, + ) + add_logging_level( + 'WEBSOCKET_DATA', + logging.DEBUG - 2, ) + format = "{asctime} [{levelname}]:{name: <20}:\t{message}" + date_format = "%Y-%m-%d %H:%M:%S" + style = '{' + if verbosity == 0: - # Only show info logging from unifi-protect-backup - logging.getLogger("pyunifiprotect").setLevel(logging.WARN) - logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN) + logging.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format) logger.setLevel(logging.INFO) elif verbosity == 1: - # Only show debug logging from unifi-protect-backup - logging.getLogger("pyunifiprotect").setLevel(logging.WARN) - logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN) + logging.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format) logger.setLevel(logging.DEBUG) elif verbosity == 2: - # Show debug logging from unifi-protect-backup and websocket data - logging.getLogger("pyunifiprotect").setLevel(logging.WARN) - logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN) - logger.setLevel(logging.WEBSOCKET_DUMP) + logging.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format) + logger.setLevel(logging.EXTRA_DEBUG) elif verbosity == 3: - # Show debug logging from unifi-protect-backup, websocket data and info from pyunifiprotect - logging.getLogger("pyunifiprotect").setLevel(logging.INFO) - logging.getLogger("pyunifiprotect.api").setLevel(logging.INFO) - logger.setLevel(logging.WEBSOCKET_DUMP) + logging.basicConfig(level=logging.INFO, format=format, style=style, datefmt=date_format) + logger.setLevel(logging.EXTRA_DEBUG) elif verbosity == 4: - # Show all debug logging - logging.getLogger("pyunifiprotect").setLevel(logging.DEBUG) - logging.getLogger("pyunifiprotect.api").setLevel(logging.DEBUG) - logger.setLevel(logging.WEBSOCKET_DUMP) + logging.basicConfig(level=logging.INFO, format=format, style=style, datefmt=date_format) + logger.setLevel(logging.WEBSOCKET_DATA) + elif verbosity == 5: + logging.basicConfig(level=logging.DEBUG, format=format, style=style, datefmt=date_format) + logger.setLevel(logging.WEBSOCKET_DATA) + + +def human_readable_size(num): + """Turns a number into a human readable number with ISO/IEC 80000 binary prefixes + + Based on: https://stackoverflow.com/a/1094933 + + Args: + num (int): The number to be converted into human readable format + """ + for unit in ["B", "KiB", "MiB", "GiB", "TiB", "PiB", "EiB", "ZiB", "YiB"]: + if abs(num) < 1024.0: + return f"{num:3.1f}{unit}" + num /= 1024.0 + raise ValueError("`num` too large, ran out of prefixes") class UnifiProtectBackup: @@ -139,18 +171,22 @@ class UnifiProtectBackup: @aiocron.crontab("0 0 * * *") async def rclone_purge_old(): logger.info("Deleting old files...") - cmd = f"rclone delete --min-age {self.retention} '{self.rclone_destination}'" - cmd += f" && rclone rmdirs --leave-root '{self.rclone_destination}'" - logger.debug(f"rclone command: {cmd}") + cmd = f"rclone delete -vv --min-age {self.retention} '{self.rclone_destination}'" + cmd += f" && rclone rmdirs -vv --leave-root '{self.rclone_destination}'" proc = await asyncio.create_subprocess_shell( cmd, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE, ) stdout, stderr = await proc.communicate() - if proc.returncode != 0: - raise Exception(stderr) - logger.info("Successfully deleted old files") + 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.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()}") logger.info("Listening for events...") await self.backup_events() @@ -160,21 +196,21 @@ class UnifiProtectBackup: async def check_rclone(self): rclone = shutil.which('rclone') - logger.debug(f"`rclone` found: {rclone}") + logger.debug(f"rclone found: {rclone}") if not rclone: raise RuntimeError("`rclone` is not installed on this system") - cmd = "rclone listremotes" - logger.debug(f"rclone command: {cmd}") + cmd = "rclone listremotes -vv" proc = await asyncio.create_subprocess_shell( cmd, stdout=asyncio.subprocess.PIPE, stderr=asyncio.subprocess.PIPE, ) stdout, stderr = await proc.communicate() + 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 Exception(f"Failed to check rclone remotes: \n{stderr}") - logger.debug(f"Found the following rclone remotes:\n{stdout.decode().strip()}") for line in stdout.splitlines(): if self.rclone_destination.startswith(line.decode()): break @@ -183,9 +219,9 @@ class UnifiProtectBackup: raise ValueError(f"rclone does not have a remote called `{remote}`") def websocket_callback(self, msg: WSSubscriptionMessage): - logger.websocket_dump(f"Got websocket message:\n{msg}") # type: ignore - # We are only interested in updates that end motion/smartdetection event + logger.websocket_data(msg) # type: ignore + # We are only interested in updates that end motion/smartdetection event assert isinstance(msg.new_obj, Event) if msg.action != WSAction.UPDATE: return @@ -193,8 +229,8 @@ class UnifiProtectBackup: return if msg.new_obj.type not in {EventType.MOTION, EventType.SMART_DETECT}: return - logger.websocket_dump("Event added to download queue") # type: ignore self._download_queue.put_nowait(msg.new_obj) + logger.debug(f"Adding event {msg.new_obj.id} to queue (Current queue={self._download_queue.qsize()})") # type: ignore async def backup_events(self): while True: @@ -202,39 +238,46 @@ class UnifiProtectBackup: 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"\tCamera: {self._camera_names[event.camera_id]}") logger.debug(f"\tType: {event.type}") logger.debug(f"\tStart: {event.start.strftime('%Y-%m-%dT%H-%M-%S')}") logger.debug(f"\tEnd: {event.end.strftime('%Y-%m-%dT%H-%M-%S')}") logger.debug(f"\tDuration: {event.end-event.start}") logger.debug(f"\tTo: {destination}") - logger.debug(f"") # TODO: Retry down/upload - + video = None try: # Download video logger.debug("\tDownloading video...") video = await self._protect.get_camera_video(event.camera_id, event.start, event.end) - - # Upload video - logger.debug("\tUploading video via rclone...") - cmd = f"rclone rcat '{destination}'" - 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: - raise Exception(stderr) - except Exception as e: - logger.warn("Failed to backup video") + logger.warn("Failed to download video") logger.exception(e) continue + logger.debug(f"\tSize: {human_readable_size(len(video))}") + + # Upload video + logger.debug("\tUploading video via rclone...") + cmd = f"rclone rcat -vv '{destination}'" + 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 + else: + logger.warn("Failed to download video") + logger.warn(f"stdout:\n{stdout.decode()}") + logger.warn(f"stderr:\n{stderr.decode()}") + continue + logger.info("Backed up successfully!") def generate_file_path(self, event):