Merge pull request #7 from exddc/improved_logging

Improved Logging

agent/VERSION

@@ -0,0 +1 @@
+0.2.0

agent/__init__.py

@@ -0,0 +1 @@
+"""Init file for the doorbell agent package."""

agent/agent.py

@@ -14,6 +14,7 @@
 import indoor_unit_agent
 import web_server
 
+
 # Load environment variables
 dotenv.load_dotenv()
 env_path = Path(".") / ".env"
@@ -22,6 +23,7 @@
 LOGGER = logger.get_module_logger(__name__)
 
 
+# pylint: disable=too-many-instance-attributes
 class Agent:
     """General Agent that creates a thread for each agent and module and runs them."""
 
@@ -30,26 +32,35 @@ def __init__(self):
         GPIO.cleanup()
         self.__agent_location = os.environ.get("AGENT_LOCATION")
         self.__agent_type = os.environ.get("AGENT_TYPE")
+        self._version = self.get_version()
         self._mqtt = mqtt_agent.MqttAgent(
             f"{self.__agent_type}_{self.__agent_location}",
             [],
+            self._version,
         )
         self._agent = None
         self._modules = []
+        self._has_internet = False
 
         self._mqtt.start()
         self._select_agent()
         self._select_modules()
 
         self._web_server = web_server.WebServer(self._mqtt)
+        self._internet_connection = threading.Thread(
+            target=self._check_internet_connection, daemon=True
+        )
 
     def run(self):
         """Run the agent and all modules"""
 
-        LOGGER.info("%s agent started.", self.__agent_type)
+        LOGGER.info(
+            "%s agent starting with version: %s", self.__agent_type, self._version
+        )
         self._agent.run()
         for module in self._modules:
             module.run()
+        self._internet_connection.start()
         self._web_server.run()
 
     def _select_agent(self):
@@ -65,6 +76,7 @@ def _select_agent(self):
     def _select_modules(self):
         """Select the modules based on the modules provided in the environment variables."""
         self.__modules = list(os.environ.get("MODULES").split(","))
+        LOGGER.debug("Modules selected: %s", self.__modules)
 
         for module in self.__modules:
             if module == "relay":
@@ -85,15 +97,41 @@ def _select_modules(self):
             else:
                 LOGGER.error(msg := "Unknown module")
                 raise NameError(msg)
+        LOGGER.debug("Modules loaded: %s", self._modules)
 
     def stop(self):
         """Stop the agent and all modules"""
         for module in self._modules:
             module.stop()
         self._agent.stop()
         self._mqtt.stop()
+        self._web_server.stop()
+        self._internet_connection.join()
         GPIO.cleanup()
-        LOGGER.info("%s agent stopped.", self.__agent_type)
+        LOGGER.info("%s %s agent stopped.", self.__agent_type, self.__agent_location)
+
+    def _check_internet_connection(self):
+        """Thread to check the internet connection and publish the status to the MQTT broker."""
+        while True:
+            if os.system("ping -c 1 www.google.com") == 0:
+                if not self._has_internet:
+                    LOGGER.info("Internet connection established.")
+                self._has_internet = True
+            else:
+                self._has_internet = False
+                LOGGER.warning("No internet connection. Retrying in 60 seconds.")
+            time.sleep(60)
+
+    @staticmethod
+    def get_version():
+        """Get the version from the VERSION file."""
+        version_file = Path(__file__).resolve().parent / "VERSION"
+        try:
+            with open(version_file, encoding="utf-8") as f:
+                return f.read().strip()
+        except FileNotFoundError:
+            LOGGER.error("VERSION file not found.")
+            return "0.0.0"
 
 
 def watch_env_file(agent_instance):
@@ -109,6 +147,7 @@ def watch_env_file(agent_instance):
                 )
                 dotenv.load_dotenv(dotenv_path=env_path, override=True)
                 agent_instance.stop()
+                LOGGER.info("Agent stopped due to .env changes. Restarting...")
                 agent_instance = Agent()
                 agent_instance.run()
                 last_mod_time = current_mod_time
@@ -119,19 +158,24 @@ def watch_env_file(agent_instance):
 
 
 if __name__ == "__main__":
-    agent = Agent()
-    agent.run()
-
-    watcher_thread = threading.Thread(target=watch_env_file, args=(agent,))
-    watcher_thread.daemon = True
-    watcher_thread.start()
-
-    try:
-        while True:
-            time.sleep(1)
-    except KeyboardInterrupt:
-        agent.stop()
-    # pylint: disable=broad-except
-    except Exception as e:
-        LOGGER.error("Agent failed: %s", str(e))
-        agent.stop()
+    while True:
+        try:
+            agent = Agent()
+            agent.run()
+
+            watcher_thread = threading.Thread(target=watch_env_file, args=(agent,))
+            watcher_thread.daemon = True
+            watcher_thread.start()
+
+            while True:
+                time.sleep(1)
+        except KeyboardInterrupt:
+            LOGGER.info("KeyboardInterrupt received. Stopping agent.")
+            agent.stop()
+            break
+        # pylint: disable=broad-except
+        except Exception as e:
+            LOGGER.error("Agent failed: %s", str(e))
+            agent.stop()
+            LOGGER.info("Restarting agent...")
+            time.sleep(0.5)

agent/base.py

@@ -5,23 +5,23 @@
 import dotenv
 import logger
 
-# import gpiozero
+import gpiozero
 
 # Load environment variables
 dotenv.load_dotenv()
 
 # Initialize logger
 LOGGER = logger.get_module_logger(__name__)
 
-""" if os.environ.get("PIN_TYPE") == "MOCK":
+if os.environ.get("PIN_TYPE") == "MOCK":
     from gpiozero.pins.mock import MockFactory
 
+    LOGGER.info("Using MockFactory for GPIO")
     gpiozero.Device.pin_factory = MockFactory()
 else:
     from gpiozero.pins.rpigpio import RPiGPIOFactory
 
     gpiozero.Device.pin_factory = RPiGPIOFactory()
- """
 
 
 # pylint: disable=too-few-public-methods
@@ -39,3 +39,4 @@ def __set_mqtt_topic(self):
         """Set the MQTT topic based on the test mode."""
         __test_mode_topic = "test/" if self._test_mode else ""
         self._mqtt_topic = f"{__test_mode_topic}doorbell"
+        LOGGER.debug("MQTT topic set to: %s", self._mqtt_topic)

agent/doorbell_agent.py

@@ -32,7 +32,7 @@ def run(self):
             self._on_doorbell_message,
         )
         LOGGER.debug("Added callback for topic: %s", self._location_topic)
-        LOGGER.info("%s listening", self._agent_location)
+        LOGGER.info("Doorbell Agent %s listening", self._agent_location)
 
         pin_map_floors = json.loads(os.environ.get("PIN_MAP_FLOORS"))
 
@@ -70,7 +70,7 @@ def button_listener(self, floor_name, pin):
                 last_pressed = datetime.datetime.now()
 
                 self._on_button_pressed(floor_name)
-                time.sleep(0.5)
+                time.sleep(0.1)
 
     # pylint: disable=unused-argument
     def _on_doorbell_message(self, client, userdata, msg):

agent/mqtt_agent.py

@@ -20,14 +20,15 @@
 class MqttAgent(paho.mqtt.client.Client):
     """MQTT Agent Module"""
 
-    def __init__(self, client_id: str, topics: list) -> None:
+    def __init__(self, client_id: str, topics: list, version: str) -> None:
         """Initialize the agent with the client ID and topics to subscribe to.
 
         param client_id: The client ID for the MQTT client.
         param topics: The topics to subscribe to.
         """
 
         self._topics = [] if topics is None else topics
+        self._version = version
         # super().__init__(paho.mqtt.client.CallbackAPIVersion.VERSION2, client_id)
         super().__init__(client_id)
 
@@ -54,6 +55,7 @@ def start(self) -> None:
         # self.on_connect = self._subscribe_on_connect
         # pylint: disable=attribute-defined-outside-init
         self.on_connect = LOGGER.info("Connected to MQTT Broker")
+        self.on_disconnect = LOGGER.warning("Disconnected from MQTT Broker")
         LOGGER.debug(
             "Connection Info: %s{}:%d",
             os.environ.get("MQTT_BROKER_IP"),
@@ -187,7 +189,11 @@ def _publish_heartbeat(self) -> None:
                 self.publish(
                     f"status/{os.environ.get('AGENT_LOCATION')}",
                     json.dumps(
-                        {"state": "online", "date": datetime.datetime.now().isoformat()}
+                        {
+                            "state": "online",
+                            "date": datetime.datetime.now().isoformat(),
+                            "version": self._version,
+                        }
                     ),
                     False,
                 )

agent/relay_agent.py

@@ -24,7 +24,7 @@ def run(self):
             f"relay/{self._agent_location}", self._on_relay_message
         )
         LOGGER.debug("Added callback for topic: relay/%s", self._agent_location)
-        LOGGER.info("%s listening", self._agent_location)
+        LOGGER.info("Relay Agent %s listening", self._agent_location)
 
     # pylint: disable=unused-argument
     def _on_relay_message(self, client, userdata, msg):

agent/rfid_agent.py

@@ -28,7 +28,7 @@ def __init__(self, mqtt_client):
     def run(self):
         """Run the agent and start listening for RFID tags."""
         self._rfid_thread.start()
-        LOGGER.info("RFID: %s listening", self._agent_location)
+        LOGGER.info("RFID Agent %s listening", self._agent_location)
 
     def _read_rfid(self):
         """Read RFID tags and publish the tag to the broker."""

agent/video_agent.py

@@ -24,6 +24,7 @@ class VideoStreamHandler(BaseHTTPRequestHandler):
     def do_GET(self):
         """Handle GET requests."""
         if self.path == "/video_stream":
+            LOGGER.info("Received video stream request")
             self.send_response(200)
             self.send_header(
                 "Content-type", "multipart/x-mixed-replace; boundary=frame"
@@ -90,6 +91,7 @@ def __init__(self, mqtt_client):
 
         if not os.path.exists(recording_folder):
             os.makedirs(recording_folder)
+            LOGGER.info("Created recording folder: %s", recording_folder)
 
         self._output = FileOutput(recording_folder + "/video_recording.h264")
 
@@ -101,8 +103,9 @@ def run(self):
             f"video/{self._agent_location}", self._on_video_message
         )
         LOGGER.debug("Added callback for topic: video/%s", self._agent_location)
-        LOGGER.info("%s listening", self._agent_location)
+        LOGGER.info("Video Agent %s listening", self._agent_location)
         if os.environ.get("VIDEO_AUTOSTART") == "True":
+            LOGGER.info("Autostarting video stream")
             self._start_video_stream()
 
     # pylint: disable=unused-argument

agent/web_server.py

@@ -42,19 +42,24 @@ def __init__(self, mqtt_client) -> None:
         # Register routes
         self._setup_routes()
 
+        self._web_server = None
+
     def _setup_routes(self) -> None:
         """Setup routes for the webserver."""
 
         @self.app.route("/")
         def dashboard():
+            LOGGER.info("Dashboard requested by %s", request.remote_addr)
             # pylint: disable=line-too-long
             stream_url = f"http://{os.popen('hostname -I').read().split()[0]}:{os.environ.get('VIDEO_STREAM_PORT')}/video_stream"
             return render_template("dashboard.html", stream_url=stream_url)
 
         @self.app.route("/settings", methods=["GET", "POST"])
         def settings():
+            LOGGER.info("Settings requested by %s", request.remote_addr)
             env_file_path = ".env"
             if request.method == "POST":
+                LOGGER.info("Updating settings.")
                 form_data = request.form.to_dict()
                 self.update_env_file(env_file_path, form_data)
                 dotenv.load_dotenv(env_file_path, override=True)
@@ -65,10 +70,12 @@ def settings():
 
         @self.app.route("/logs", methods=["GET", "POST"])
         def logs():
+            LOGGER.info("Logs requested by %s", request.remote_addr)
             lines = int(request.form.get("lines", 25))
             log_file_path = "./logs/agent.log"
             logs = self.tail(log_file_path, lines)
             if request.headers.get("HX-Request"):
+                LOGGER.debug("Returning partial log view.")
                 return render_template("partials/log_view.html", logs=logs)
             return render_template("logs.html", logs=logs, selected_lines=lines)
 
@@ -80,9 +87,17 @@ def run(self) -> None:
             self._on_doorbell_message,
         )
         LOGGER.info("Webserver subscribed to MQTT topic: %s", self._location_topic)
-        waitress.serve(self.app, host="0.0.0.0", port=self._port)
+        self._web_server = waitress.serve(self.app, host="0.0.0.0", port=self._port)
         LOGGER.info("Webserver started on port %i.", self._port)
 
+    def stop(self) -> None:
+        """Stop the webserver."""
+        self._web_server.close()
+        self._mqtt.unsubscribe(self._location_topic)
+        LOGGER.info("Webserver unsubscribed from MQTT topic: %s", self._location_topic)
+        self._mqtt.message_callback_remove(self._location_topic)
+        LOGGER.info("Webserver stopped.")
+
     # pylint: disable=unused-argument
     def _on_doorbell_message(self, client, userdata, msg):
         """Process the doorbell message.
@@ -129,6 +144,7 @@ def read_env_file(file_path):
                     }
                 )
 
+        LOGGER.info("Read .env file successfully.")
         return sections
 
     @staticmethod
@@ -164,12 +180,16 @@ def update_env_file(file_path, form_data):
                 else:
                     file.write(line)
 
+        LOGGER.info("Updated .env file successfully.")
+
     @staticmethod
     def tail(file_path, lines=25):
         """Read the last N lines from a file."""
         if not os.path.exists(file_path):
+            LOGGER.error("Log file not found.")
             return ["Log file not found."]
         if os.stat(file_path).st_size == 0:
+            LOGGER.error("Log file is empty.")
             return ["Log file is empty."]
 
         with open(file_path, "r", encoding="utf-8") as file: