feat(LOGGING): add logging to slack bot and client

pi_portal/cli.py

@@ -32,7 +32,7 @@ def monitor(ctx: click.Context) -> None:
   door_monitor = integrations.door_monitor.DoorMonitor()
   door_monitor.log = ctx.obj['logging_config'].configure(
       door_monitor.log,
-      config.LOGFILE_PATH,
+      config.DOOR_MONITOR_LOGFILE_PATH,
   )
   door_monitor.start()
 

pi_portal/config.py

@@ -20,6 +20,8 @@ class DoorNames(Enum):
     2: None
 }
 
-LOGFILE_PATH = "/var/log/pi_portal.log"
+DOOR_MONITOR_LOGFILE_PATH = "/var/log/pi_portal.door.log"
+SLACK_BOT_LOGFILE_PATH = "/var/log/pi_portal.slack_bot.log"
+SLACK_CLIENT_LOGFILE_PATH = "/var/log/pi_portal.slack_client.log"
 MOTION_FOLDER = "/var/lib/motion"
 SUPERVISOR_SOCKET_PATH = "/var/run/supervisor.sock"

pi_portal/installation/filebeat/filebeat.yml

@@ -4,7 +4,7 @@ filebeat.inputs:
 
 - type: log
   paths:
-    - /var/log/pi_portal.log
+    - /var/log/pi_portal.door.log
   fields:
     logzio_codec: plain
     token: <<LOGZ_IO_CODE>>
@@ -13,6 +13,18 @@ filebeat.inputs:
   encoding: utf-8
   ignore_older: 12h
 
+- type: log
+  paths:
+    - /var/log/pi_portal.slack_bot.log
+    - /var/log/pi_portal.slack_client.log
+  fields:
+    logzio_codec: plain
+    token: <<LOGZ_IO_CODE>>
+    type: pi_portal_slack
+  fields_under_root: true
+  encoding: utf-8
+  ignore_older: 12h
+
 - type: log
   paths:
     - /var/log/syslog

pi_portal/installation/scripts/install.sh

@@ -2,6 +2,12 @@
 
 SCRIPT_DIR="$( cd -- "$( dirname -- "${BASH_SOURCE[0]}" )" &> /dev/null && pwd )"
 
+
+configure_log_file() {
+  touch "$1"
+  chown pi_portal:pi_portal "$1"
+}
+
 configure_motion() {
   service motion stop
   update-rc.d -f motion remove
@@ -13,14 +19,12 @@ configure_motion() {
 
 configure_pi_portal() {
   mkdir -p /opt/pi_portal
-  touch /var/log/pi_portal.log
 
   cp ./installation/scripts/portal.sh /opt/pi_portal/portal.sh
   cp "${CONFIG_FILE}" /opt/pi_portal/config.json
 
   chmod +x /opt/pi_portal/portal.sh
   chown -R pi_portal:pi_portal /opt/pi_portal
-  chown pi_portal:pi_portal /var/log/pi_portal.log
   chmod 700 /opt/pi_portal/config.json
 }
 
@@ -63,6 +67,10 @@ main() {
 
     install_filebeat
 
+    configure_log_file "/var/log/pi_portal.door.log"
+    configure_log_file "/var/log/pi_portal.slack_bot.log"
+    configure_log_file "/var/log/pi_portal.slack_client.log"
+
     configure_supervisor
     configure_pi_portal
     configure_motion

pi_portal/modules/configuration/tests/fixtures/mock_state.py

@@ -12,6 +12,7 @@
 MOCK_SLACK_CHANNEL_ID = "CHHH111"
 MOCK_SLACK_TOKEN = "secretValue"
 MOCK_S3_BUCKET_NAME = 'MOCK_S3_BUCKET_NAME'
+MOCK_LOG_UUID = "MOCK_UUID_VALUE"
 
 TypeReturn = TypeVar("TypeReturn")
 
@@ -31,7 +32,7 @@ def patched_function(*args: Any, **kwargs: Any) -> TypeReturn:
           "SLACK_CHANNEL_ID": MOCK_SLACK_CHANNEL_ID,
           "S3_BUCKET_NAME": MOCK_S3_BUCKET_NAME,
       }
-      mock_state.return_value.log_uuid = "test_uuid"
+      mock_state.return_value.log_uuid = MOCK_LOG_UUID
 
       return func(*args, **kwargs)
 

pi_portal/modules/integrations/slack/bot.py

@@ -1,8 +1,10 @@
 """Pi Portal Slack RTM bot."""
 
+from pi_portal import config
 from pi_portal.modules.configuration import state
 from pi_portal.modules.integrations.slack import cli, client
 from pi_portal.modules.integrations.slack.cli import handler
+from pi_portal.modules.mixins import log_file
 from slack_sdk.rtm_v2 import RTMClient
 from typing_extensions import TypedDict
 
@@ -14,11 +16,15 @@ class TypeEvent(TypedDict):
   text: str
 
 
-class SlackBot:
+class SlackBot(log_file.WriteLogFile):
   """Slack RTM bot."""
 
+  logger_name = "bot"
+  log_file_path = config.SLACK_BOT_LOGFILE_PATH
+
   def __init__(self) -> None:
     current_state = state.State()
+    self.configure_logger()
     self.rtm = RTMClient(token=current_state.user_config["SLACK_BOT_TOKEN"])
     self.channel_id = current_state.user_config['SLACK_CHANNEL_ID']
     self.command_list = cli.get_available_commands()
@@ -39,6 +45,7 @@ def receiver(_: RTMClient, event: TypeEvent) -> None:
     self.slack_client.send_message(
         "I've rebooted!  Now listening for commands..."
     )
+    self.log.warning("Slack Bot process has started.")
     self.rtm.start()
 
   def handle_event(self, event: TypeEvent) -> None:
@@ -64,6 +71,8 @@ def handle_command(self, command: str) -> None:
     :param command: The Slack CLI command to handle.
     """
 
+    self.log.debug("Received command: '%s'", command)
     if command in self.command_list:
+      self.log.info("Executing valid command: '%s'", command)
       command_handler = handler.SlackCLICommandHandler(bot=self)
       getattr(command_handler, command_handler.method_prefix + command)()

pi_portal/modules/integrations/slack/client.py

@@ -1,19 +1,24 @@
 """Pi Portal Slack messaging client."""
 
+from pi_portal import config
 from pi_portal.modules.configuration import state
 from pi_portal.modules.integrations import motion
 from pi_portal.modules.integrations.slack import config as slack_config
+from pi_portal.modules.mixins import log_file
 from slack_sdk import WebClient
 from slack_sdk.errors import SlackApiError, SlackRequestError
 
 
-class SlackClient:
+class SlackClient(log_file.WriteLogFile):
   """Slack messaging client."""
 
+  logger_name = "client"
+  log_file_path = config.SLACK_CLIENT_LOGFILE_PATH
   retries = 5
 
   def __init__(self) -> None:
     current_state = state.State()
+    self.configure_logger()
     self.web = WebClient(token=current_state.user_config['SLACK_BOT_TOKEN'])
     self.channel = current_state.user_config['SLACK_CHANNEL']
     self.motion_client = motion.Motion()
@@ -30,7 +35,7 @@ def send_message(self, message: str) -> None:
         self.web.chat_postMessage(channel=self.channel, text=message)
         break
       except (SlackRequestError, SlackApiError):
-        pass
+        self.log.error("Failed to send message: '%s'", message)
 
   def send_file(self, file_name: str) -> None:
     """Send a file with the Slack Web client.
@@ -47,7 +52,7 @@ def send_file(self, file_name: str) -> None:
         )
         break
       except (SlackRequestError, SlackApiError):
-        pass
+        self.log.error("Failed to send file: '%s'", file_name)
 
   def send_snapshot(self, file_name: str) -> None:
     """Send a snapshot to Slack, and erase it locally.
@@ -60,6 +65,7 @@ def send_snapshot(self, file_name: str) -> None:
       self.motion_client.cleanup_snapshot(file_name)
     except motion.MotionException:
       self.send_message("An error occurred cleaning up this snapshot.")
+      self.log.error("Failed to remove old motion snapshot!")
 
   def send_video(self, file_name: str) -> None:
     """Send a video to Slack, and have motion archive it in S3.
@@ -72,3 +78,4 @@ def send_video(self, file_name: str) -> None:
       self.motion_client.archive_video(file_name)
     except motion.MotionException:
       self.send_message("An error occurred archiving this video.")
+      self.log.error("Failed to archive motion video capture!")

pi_portal/modules/integrations/slack/tests/test_bot.py

@@ -1,5 +1,5 @@
 """Test the SlackBot class."""
-
+import logging
 from typing import cast
 from unittest import TestCase, mock
 
@@ -18,10 +18,15 @@ def setUp(self) -> None:
     self.bot = bot.SlackBot()
     self.bot.slack_client = mock.MagicMock()
     self.bot.command_list = self.command_list
+    self.bot.log = mock.Mock()
+
+  def _mock_log(self) -> mock.Mock:
+    return cast(mock.Mock, self.bot.log)
 
   @mock_state.patch
   def test_initialize(self) -> None:
     slack_bot = bot.SlackBot()
+    self.assertIsInstance(slack_bot.log, logging.Logger)
     self.assertEqual(slack_bot.rtm.token, mock_state.MOCK_SLACK_TOKEN)
     self.assertEqual(slack_bot.channel_id, mock_state.MOCK_SLACK_CHANNEL_ID)
     self.assertListEqual(slack_bot.command_list, cli.get_available_commands())
@@ -34,12 +39,21 @@ def test_handle_command_valid(self, m_slack_cli: mock.Mock) -> None:
     self.bot.handle_command(self.test_command)
     m_slack_cli.assert_called_once_with(bot=self.bot)
     m_slack_cli.return_value.command_id.assert_called_once_with()
+    self._mock_log().debug.assert_called_once_with(
+        "Received command: '%s'", self.test_command
+    )
+    self._mock_log().info.assert_called_once_with(
+        "Executing valid command: '%s'", self.test_command
+    )
 
   @mock.patch(slack.__name__ + ".cli.handler.SlackCLICommandHandler")
   def test_handle_command_invalid(self, m_slack_cli: mock.Mock) -> None:
     invalid_command = "Invalid Command"
     self.bot.handle_command(invalid_command)
     m_slack_cli.return_value.command_id.assert_not_called()
+    self._mock_log().debug.assert_called_once_with(
+        "Received command: '%s'", invalid_command
+    )
 
   def test_handle_event_valid(self) -> None:
     test_event = bot.TypeEvent(

pi_portal/modules/integrations/slack/tests/test_client.py

@@ -16,10 +16,14 @@ class TestSlackClient(TestCase):
   def setUp(self) -> None:
     self.slack_client = client.SlackClient()
     self.slack_client.motion_client = mock.MagicMock()
+    self.slack_client.log = mock.Mock()
 
   def _mock_motion_client(self) -> mock.Mock:
     return cast(mock.Mock, self.slack_client.motion_client)
 
+  def _mock_log(self) -> mock.Mock:
+    return cast(mock.Mock, self.slack_client.log)
+
   @mock_state.patch
   def test_initialize(self) -> None:
     slack_client = client.SlackClient()
@@ -49,6 +53,11 @@ def test_send_message_exception(self) -> None:
             text=test_message,
         )] * self.slack_client.retries
     )
+    self.assertListEqual(
+        self._mock_log().error.mock_calls,
+        [mock.call("Failed to send message: '%s'", test_message)] *
+        self.slack_client.retries
+    )
 
   def test_send_file(self) -> None:
     test_file = "/path/to/mock/file.txt"
@@ -76,6 +85,11 @@ def test_send_file_exception(self) -> None:
             )
         ] * self.slack_client.retries
     )
+    self.assertListEqual(
+        self._mock_log().error.mock_calls,
+        [mock.call("Failed to send file: '%s'", test_file)] *
+        self.slack_client.retries
+    )
 
   def test_send_snapshot(self) -> None:
     test_snapshot = "/path/to/mock/snapshot.jpg"
@@ -90,17 +104,22 @@ def test_send_snapshot_exception(self) -> None:
     test_snapshot = "/path/to/mock/snapshot.jpg"
     with mock.patch.object(self.slack_client, "send_file") as m_send:
       with mock.patch.object(self.slack_client, "web") as m_web:
-        self._mock_motion_client(
-        ).cleanup_snapshot.side_effect = (motion.MotionException("Boom!"))
+        self._mock_motion_client().cleanup_snapshot.side_effect = (
+          motion.MotionException("Boom!"),
+        )
         self.slack_client.send_snapshot(test_snapshot)
 
     m_send.assert_called_once_with(test_snapshot)
-    self._mock_motion_client(
-    ).cleanup_snapshot.assert_called_once_with(test_snapshot)
+    self._mock_motion_client().cleanup_snapshot.assert_called_once_with(
+      test_snapshot,
+    )
     m_web.chat_postMessage.assert_called_once_with(
         channel=self.slack_client.channel,
         text="An error occurred cleaning up this snapshot.",
     )
+    self._mock_log().error.assert_called_once_with(
+      'Failed to remove old motion snapshot!',
+    )
 
   def test_send_video(self) -> None:
     test_video = "/path/to/mock/video.mp4"
@@ -124,3 +143,6 @@ def test_send_video_exception(self) -> None:
         channel=self.slack_client.channel,
         text="An error occurred archiving this video.",
     )
+    self._mock_log().error.assert_called_once_with(
+      "Failed to archive motion video capture!",
+    )

pi_portal/modules/mixins/log_file.py

@@ -0,0 +1,20 @@
+"""Standard logging mixin class."""
+
+from logging import Logger, getLogger
+
+from pi_portal.modules.configuration import logger
+
+
+class WriteLogFile:
+  """Adds logging features to an existing class."""
+
+  logger_name: str
+  log_file_path: str
+  log: Logger
+
+  def configure_logger(self) -> None:
+    """Configure a standardized logger for this class."""
+
+    self.log = getLogger(self.logger_name)
+    logging_configuration = logger.LoggingConfiguration()
+    logging_configuration.configure(self.log, self.log_file_path)

pi_portal/modules/mixins/tests/test_logging.py

@@ -0,0 +1,39 @@
+"""Test the WriteLogFile mixin classes."""
+
+from unittest import TestCase, mock
+
+from .. import log_file
+
+LOG_FILE_MODULE = log_file.__name__
+
+
+class ClassWithLogging(log_file.WriteLogFile):
+  """A test class using the WriteLogFile mixin."""
+
+  logger_name = "test_logger"
+  log_file_path = "/var/run/some.log"
+
+
+@mock.patch(LOG_FILE_MODULE + '.getLogger')
+@mock.patch(LOG_FILE_MODULE + '.logger.LoggingConfiguration')
+class WriteLogFileTest(TestCase):
+  """Test the WriteLogFile mixin class."""
+
+  def setUp(self) -> None:
+    self.instance = ClassWithLogging()
+
+  def test_configure_logger(
+      self,
+      m_config: mock.Mock,
+      m_get: mock.Mock,
+  ) -> None:
+
+    self.instance.configure_logger()
+
+    m_get.assert_called_once_with(self.instance.logger_name)
+    m_config.assert_called_once_with()
+    m_config.return_value.configure.assert_called_once_with(
+        m_get.return_value, self.instance.log_file_path
+    )
+
+    self.assertEqual(self.instance.log, m_get.return_value)