Merge pull request #97 from aviate-labs/90-implement-logging-solution

90 implement logging solution

CHANGELOG.md

@@ -8,6 +8,8 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 ## [Unreleased]
 <!-- ## [1.0.0-alpha.2] - Unreleased -->
 
+- Added logging.
+
 
 ## [1.0.0-alpha.1] - 2023-10-20
 

Makefile

@@ -15,7 +15,7 @@ dev:
 
 # Run this with the production gunicorn WSGI Server
 prod:
-	gunicorn -w 1 -b 0.0.0.0:80 --access-logfile gunicornlog.txt -k eventlet node_monitor.__main__:app
+	gunicorn -w 1 -b 0.0.0.0:80 --access-logfile=logs/gunicorn_access.log --error-logfile=logs/gunicorn_error.log -k eventlet node_monitor.__main__:app
 # We're forced to run this with only one worker because we're instantiating
 # node_monitor in a thread from inside the app. If we had multiple workers,
 # we would have multiple instances of node_monitor running, each sending

README.md

@@ -39,6 +39,14 @@ $ make prod
 For more control over testing, see `tests/conftest.py`, and/or `Makefile`.
 
 
+## Logging
+
+Node Monitor writes all logs to the `logs/` directory.  
+- `logs/gunicorn_access.log` contains all HTTP requests.
+- `logs/gunicorn_error.log` contains all gunicorn errors and information.
+- `logs/node_monitor.log` contains all `Node Monitor` specific logs.
+
+
 
 ## Notes
 

node_monitor/__main__.py

@@ -1,4 +1,5 @@
 import threading
+import logging
 
 from node_monitor.bot_email import EmailBot
 from node_monitor.bot_slack import SlackBot
@@ -9,7 +10,16 @@
 import node_monitor.load_config as c
 
 
-## Initialize
+## Calling `basicConfig` will globally overwrite the root logging 
+## configuration, so changes propagate to all loggers in the application.
+logging.basicConfig(
+    level=logging.INFO,
+    format='%(asctime)s - %(levelname)s: %(message)s',
+    datefmt='[%Y-%m-%d %H:%M:%S %z]', # Uses the same format as Gunicorn
+    filename='logs/node_monitor.log',
+)
+
+## Initialize Node Monitor
 ## Objects are passed by reference, so we can pass around the NodeMonitor
 ## instance and work on the same data in different functions/threads
 email_bot = EmailBot(c.EMAIL_USERNAME, c.EMAIL_PASSWORD)
@@ -25,10 +35,10 @@
 ## can we call nm.mainloop as the target without creating a new fn?
 def start_node_monitor() -> None:
     nm.mainloop()
-print("Starting NodeMonitor...", end=" ")
+logging.info("Starting NodeMonitor...")
 thread = threading.Thread(target=start_node_monitor, daemon=True)
 thread.start()
-print("Running.")
+logging.info("NodeMonitor is running.")
 
 ## Run Flask server in main thread
 app = create_server(nm, thread.is_alive)

node_monitor/node_monitor.py

@@ -3,6 +3,7 @@
 from typing import Deque, List, Dict, Optional
 from toolz import groupby # type: ignore
 import schedule
+import logging
 
 import node_monitor.ic_api as ic_api
 from node_monitor.bot_email import EmailBot
@@ -74,6 +75,7 @@ def _resync(self, override_data: ic_api.Nodes | None = None) -> None:
             override_data: If provided, this arg will be used instead of 
                 live fetching Nodes from the ic-api. Useful for testing.
         """
+        logging.info("Resyncing node states from ic-api...")
         data = override_data if override_data else ic_api.get_nodes()
         self.snapshots.append(data)
         self.last_update = time.time()
@@ -111,15 +113,22 @@ def broadcast_alerts(self) -> None:
             # - - - - - - - - - - - - - - - - -
             if preferences['notify_email'] == True:
                 recipients = email_recipients[node_provider_id]
+                logging.info(f"Sending alert email message to {recipients}...")
                 self.email_bot.send_emails(recipients, subject, message)
             if preferences['notify_slack'] == True: 
                 if self.slack_bot is not None:
                     channel_name = channels[node_provider_id]['slack_channel_name']
-                    self.slack_bot.send_message(channel_name, message)
+                    logging.info(f"Sending alert slack message to {channel_name}...")
+                    err1 = self.slack_bot.send_message(channel_name, message)
+                    if err1 is not None:
+                        logging.error(f"SlackBot.send_message() failed with error: {err1}")
             if preferences['notify_telegram_chat'] == True:
                 if self.telegram_bot is not None:
                     chat_id = channels[node_provider_id]['telegram_chat_id']
-                    self.telegram_bot.send_message(chat_id, message)
+                    logging.info(f"Sending alert telegram message to {chat_id}...")
+                    err2 = self.telegram_bot.send_message(chat_id, message)
+                    if err2 is not None:
+                        logging.error(f"TelegramBot.send_message() failed with error: {err2}")
             # - - - - - - - - - - - - - - - - -
 
 
@@ -141,20 +150,28 @@ def broadcast_status_report(self) -> None:
                             if k in subscribers.keys()}
         # - - - - - - - - - - - - - - - - -
         for node_provider_id, nodes in reportable_nodes.items():
+            logging.info(f"Broadcasting status report {node_provider_id}...")
             preferences = subscribers[node_provider_id]
             subject, message = messages.nodes_status_message(nodes, node_labels)
             # - - - - - - - - - - - - - - - - -
             if preferences['notify_email'] == True:
                 recipients = email_recipients[node_provider_id]
+                logging.info(f"Sending status report email to {recipients}...")
                 self.email_bot.send_emails(recipients, subject, message)
             if preferences['notify_slack'] == True:
                 if self.slack_bot is not None:
                     channel_name = channels[node_provider_id]['slack_channel_name']
-                    self.slack_bot.send_message(channel_name, message)
+                    logging.info(f"Sending status report slack message to {channel_name}...")
+                    err1 = self.slack_bot.send_message(channel_name, message)
+                    if err1 is not None:
+                        logging.error(f"SlackBot.send_message() failed with error: {err1}")
             if preferences['notify_telegram_chat'] == True: 
                 if self.telegram_bot is not None:
                     chat_id = channels[node_provider_id]['telegram_chat_id']
-                    self.telegram_bot.send_message(chat_id, message)
+                    logging.info(f"Sending status report telegram message to {chat_id}...")
+                    err2 = self.telegram_bot.send_message(chat_id, message)
+                    if err2 is not None:
+                        logging.error(f"TelegramBot.send_message() failed with error: {err2}")
             # - - - - - - - - - - - - - - - - -
 
 
@@ -167,7 +184,7 @@ def step(self) -> None:
             self._analyze()
             self.broadcast_alerts()
         except Exception as e:
-            print(f"NodeMonitor.step() failed with error: {e}")
+            logging.error(f"NodeMonitor.step() failed with error: {e}")
 
 
     def mainloop(self) -> None: