diff --git a/pi_portal/cli.py b/pi_portal/cli.py index ef8b79ef..34639ae6 100644 --- a/pi_portal/cli.py +++ b/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() diff --git a/pi_portal/config.py b/pi_portal/config.py index 20b88351..985d3c7e 100644 --- a/pi_portal/config.py +++ b/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" diff --git a/pi_portal/installation/filebeat/filebeat.yml b/pi_portal/installation/filebeat/filebeat.yml index 02dd2772..2efa7c39 100644 --- a/pi_portal/installation/filebeat/filebeat.yml +++ b/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: <> @@ -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: <> + type: pi_portal_slack + fields_under_root: true + encoding: utf-8 + ignore_older: 12h + - type: log paths: - /var/log/syslog diff --git a/pi_portal/installation/scripts/install.sh b/pi_portal/installation/scripts/install.sh index b4ff1465..502108cc 100644 --- a/pi_portal/installation/scripts/install.sh +++ b/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 diff --git a/pi_portal/modules/configuration/tests/fixtures/mock_state.py b/pi_portal/modules/configuration/tests/fixtures/mock_state.py index a8e5a285..7452ab19 100644 --- a/pi_portal/modules/configuration/tests/fixtures/mock_state.py +++ b/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) diff --git a/pi_portal/modules/integrations/slack/bot.py b/pi_portal/modules/integrations/slack/bot.py index 918eb0bc..03a3d326 100644 --- a/pi_portal/modules/integrations/slack/bot.py +++ b/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)() diff --git a/pi_portal/modules/integrations/slack/client.py b/pi_portal/modules/integrations/slack/client.py index 479f2d4d..28fdc35e 100644 --- a/pi_portal/modules/integrations/slack/client.py +++ b/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!") diff --git a/pi_portal/modules/integrations/slack/tests/test_bot.py b/pi_portal/modules/integrations/slack/tests/test_bot.py index 3bfdd757..92704829 100644 --- a/pi_portal/modules/integrations/slack/tests/test_bot.py +++ b/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( diff --git a/pi_portal/modules/integrations/slack/tests/test_client.py b/pi_portal/modules/integrations/slack/tests/test_client.py index 0cb7889c..04ddd06d 100644 --- a/pi_portal/modules/integrations/slack/tests/test_client.py +++ b/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!", + ) diff --git a/pi_portal/modules/mixins/log_file.py b/pi_portal/modules/mixins/log_file.py new file mode 100644 index 00000000..d6faa6b4 --- /dev/null +++ b/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) diff --git a/pi_portal/modules/mixins/tests/test_logging.py b/pi_portal/modules/mixins/tests/test_logging.py new file mode 100644 index 00000000..d4e91120 --- /dev/null +++ b/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)