Overhauled logging

- Better logging format
- More information logged
- Ability to show rclone logging

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):
+def setup_logging(verbosity: int) -> None:
-    logging.basicConfig(level=logging.INFO)
+    """Configures loggers to provided the desired level of verbosity
-    addLoggingLevel(
+
-        'WEBSOCKET_DUMP',
+    Verbosity 0: Only log info messages created by `unifi-protect-backup`, and all warnings
-        logging.DEBUG - 5,
+    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.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format)
-        logging.getLogger("pyunifiprotect").setLevel(logging.WARN)
-        logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN)
         logger.setLevel(logging.INFO)
     elif verbosity == 1:
-        # Only show debug logging from unifi-protect-backup
+        logging.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format)
-        logging.getLogger("pyunifiprotect").setLevel(logging.WARN)
-        logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN)
         logger.setLevel(logging.DEBUG)
     elif verbosity == 2:
-        # Show debug logging from unifi-protect-backup and websocket data
+        logging.basicConfig(level=logging.WARN, format=format, style=style, datefmt=date_format)
-        logging.getLogger("pyunifiprotect").setLevel(logging.WARN)
+        logger.setLevel(logging.EXTRA_DEBUG)
-        logging.getLogger("pyunifiprotect.api").setLevel(logging.WARN)
-        logger.setLevel(logging.WEBSOCKET_DUMP)
     elif verbosity == 3:
-        # Show debug logging from unifi-protect-backup, websocket data and info from pyunifiprotect
+        logging.basicConfig(level=logging.INFO, format=format, style=style, datefmt=date_format)
-        logging.getLogger("pyunifiprotect").setLevel(logging.INFO)
+        logger.setLevel(logging.EXTRA_DEBUG)
-        logging.getLogger("pyunifiprotect.api").setLevel(logging.INFO)
-        logger.setLevel(logging.WEBSOCKET_DUMP)
     elif verbosity == 4:
-        # Show all debug logging
+        logging.basicConfig(level=logging.INFO, format=format, style=style, datefmt=date_format)
-        logging.getLogger("pyunifiprotect").setLevel(logging.DEBUG)
+        logger.setLevel(logging.WEBSOCKET_DATA)
-        logging.getLogger("pyunifiprotect.api").setLevel(logging.DEBUG)
+    elif verbosity == 5:
-        logger.setLevel(logging.WEBSOCKET_DUMP)
+        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 delete -vv --min-age {self.retention} '{self.rclone_destination}'"
-            cmd += f" && rclone rmdirs --leave-root '{self.rclone_destination}'"
+            cmd += f" && rclone rmdirs -vv --leave-root '{self.rclone_destination}'"
-            logger.debug(f"rclone command: {cmd}")
             proc = await asyncio.create_subprocess_shell(
                 cmd,
                 stdout=asyncio.subprocess.PIPE,
                 stderr=asyncio.subprocess.PIPE,
             )
             stdout, stderr = await proc.communicate()
-            if proc.returncode != 0:
+            if proc.returncode == 0:
-                raise Exception(stderr)
+                logger.extra_debug(f"stdout:\n{stdout.decode()}")  # type: ignore
-            logger.info("Successfully deleted old files")
+                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"
+        cmd = "rclone listremotes -vv"
-        logger.debug(f"rclone command: {cmd}")
         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
+        logger.websocket_data(msg)  # type: ignore
-        # We are only interested in updates that end motion/smartdetection event
 
+        # 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):