added logging to modules

dune_weaver_flask/modules/core/pattern_manager.py

@@ -2,10 +2,14 @@ import os
 import threading
 import time
 import random
+import logging
 from datetime import datetime
 from tqdm import tqdm
 from dune_weaver_flask.modules.serial import serial_manager
 
+# Configure logging
+logger = logging.getLogger(__name__)
+
 # Global state
 THETA_RHO_DIR = './patterns'
 CLEAR_PATTERNS = {
@@ -31,12 +35,14 @@ def list_theta_rho_files():
         for file in filenames:
             relative_path = os.path.relpath(os.path.join(root, file), THETA_RHO_DIR)
             files.append(relative_path)
+    logger.debug(f"Found {len(files)} theta-rho files")
     return files
 
 def parse_theta_rho_file(file_path):
     """Parse a theta-rho file and return a list of (theta, rho) pairs."""
     coordinates = []
     try:
+        logger.debug(f"Parsing theta-rho file: {file_path}")
         with open(file_path, 'r') as file:
             for line in file:
                 line = line.strip()
@@ -46,10 +52,10 @@ def parse_theta_rho_file(file_path):
                     theta, rho = map(float, line.split())
                     coordinates.append((theta, rho))
                 except ValueError:
-                    print(f"Skipping invalid line: {line}")
+                    logger.warning(f"Skipping invalid line: {line}")
                     continue
     except Exception as e:
-        print(f"Error reading file: {e}")
+        logger.error(f"Error reading file: {e}")
         return coordinates
 
     # Normalization Step
@@ -57,6 +63,7 @@ def parse_theta_rho_file(file_path):
         first_theta = coordinates[0][0]
         normalized = [(theta - first_theta, rho) for theta, rho in coordinates]
         coordinates = normalized
+        logger.debug(f"Parsed {len(coordinates)} coordinates from {file_path}")
 
     return coordinates
 
@@ -88,13 +95,13 @@ def schedule_checker(schedule_hours):
 
     if start_time <= now < end_time:
         if pause_requested:
-            print("Starting execution: Within schedule.")
+            logger.info("Starting execution: Within schedule")
         pause_requested = False
         with pause_condition:
             pause_condition.notify_all()
     else:
         if not pause_requested:
-            print("Pausing execution: Outside schedule.")
+            logger.info("Pausing execution: Outside schedule")
         pause_requested = True
         threading.Thread(target=wait_for_start_time, args=(schedule_hours,), daemon=True).start()
 
@@ -106,7 +113,7 @@ def wait_for_start_time(schedule_hours):
     while pause_requested:
         now = datetime.now().time()
         if start_time <= now < end_time:
-            print("Resuming execution: Within schedule.")
+            logger.info("Resuming execution: Within schedule")
             pause_requested = False
             with pause_condition:
                 pause_condition.notify_all()
@@ -121,7 +128,7 @@ def run_theta_rho_file(file_path, schedule_hours=None):
     total_coordinates = len(coordinates)
 
     if total_coordinates < 2:
-        print("Not enough coordinates for interpolation.")
+        logger.warning("Not enough coordinates for interpolation")
         current_playing_file = None
         execution_progress = None
         return
@@ -134,15 +141,16 @@ def run_theta_rho_file(file_path, schedule_hours=None):
         current_playing_file = file_path
         execution_progress = (0, 0, None)
         stop_requested = False
+        logger.info(f"Starting pattern execution: {file_path}")
         with tqdm(total=total_coordinates, unit="coords", desc=f"Executing Pattern {file_path}", dynamic_ncols=True, disable=None) as pbar:
             for i in range(0, total_coordinates, batch_size):
                 if stop_requested:
-                    print("Execution stopped by user after completing the current batch.")
+                    logger.info("Execution stopped by user after completing the current batch")
                     break
 
                 with pause_condition:
                     while pause_requested:
-                        print("Execution paused...")
+                        logger.info("Execution paused...")
                         pause_condition.wait()
 
                 batch = coordinates[i:i + batch_size]
@@ -164,22 +172,21 @@ def run_theta_rho_file(file_path, schedule_hours=None):
                             execution_progress = (i + batch_size, total_coordinates, estimated_remaining_time)
                             break
                         elif response != "IGNORED: FINISHED" and response.startswith("IGNORE"):
-                            print("Received IGNORE. Resending the previous batch...")
-                            print(response)
+                            logger.warning(f"Received IGNORE response: {response}")
                             prev_start = max(0, i - batch_size)
                             prev_end = i
                             previous_batch = coordinates[prev_start:prev_end]
                             serial_manager.send_coordinate_batch(previous_batch)
                             break
                         else:
-                            print(f"Arduino response: {response}")
+                            logger.debug(f"Arduino response: {response}")
 
         reset_theta()
         serial_manager.ser.write("FINISHED\n".encode())
 
     current_playing_file = None
     execution_progress = None
-    print("Pattern execution completed.")
+    logger.info("Pattern execution completed")
 
 def run_theta_rho_files(file_paths, pause_time=0, clear_pattern=None, run_mode="single", shuffle=False, schedule_hours=None):
     """Run multiple .thr files in sequence with options."""
@@ -188,70 +195,71 @@ def run_theta_rho_files(file_paths, pause_time=0, clear_pattern=None, run_mode="
     
     if shuffle:
         random.shuffle(file_paths)
-        print("Playlist shuffled.")
+        logger.info("Playlist shuffled")
 
     current_playlist = file_paths
 
     while True:
         for idx, path in enumerate(file_paths):
-            print("Upcoming pattern: " + path)
+            logger.info(f"Upcoming pattern: {path}")
             current_playing_index = idx
             schedule_checker(schedule_hours)
             if stop_requested:
-                print("Execution stopped before starting next pattern.")
+                logger.info("Execution stopped before starting next pattern")
                 return
 
             if clear_pattern:
                 if stop_requested:
-                    print("Execution stopped before running the next clear pattern.")
+                    logger.info("Execution stopped before running the next clear pattern")
                     return
 
                 clear_file_path = get_clear_pattern_file(clear_pattern, path)
-                print(f"Running clear pattern: {clear_file_path}")
+                logger.info(f"Running clear pattern: {clear_file_path}")
                 run_theta_rho_file(clear_file_path, schedule_hours)
 
             if not stop_requested:
-                print(f"Running pattern {idx + 1} of {len(file_paths)}: {path}")
+                logger.info(f"Running pattern {idx + 1} of {len(file_paths)}: {path}")
                 run_theta_rho_file(path, schedule_hours)
 
             if idx < len(file_paths) - 1:
                 if stop_requested:
-                    print("Execution stopped before running the next clear pattern.")
+                    logger.info("Execution stopped before running the next clear pattern")
                     return
                 if pause_time > 0:
-                    print(f"Pausing for {pause_time} seconds...")
+                    logger.debug(f"Pausing for {pause_time} seconds")
                     time.sleep(pause_time)
 
         if run_mode == "indefinite":
-            print("Playlist completed. Restarting as per 'indefinite' run mode.")
+            logger.info("Playlist completed. Restarting as per 'indefinite' run mode")
             if pause_time > 0:
-                print(f"Pausing for {pause_time} seconds before restarting...")
+                logger.debug(f"Pausing for {pause_time} seconds before restarting")
                 time.sleep(pause_time)
             if shuffle:
                 random.shuffle(file_paths)
-                print("Playlist reshuffled for the next loop.")
+                logger.info("Playlist reshuffled for the next loop")
             continue
         else:
-            print("Playlist completed.")
+            logger.info("Playlist completed")
             break
 
     reset_theta()
     with serial_manager.serial_lock:
         serial_manager.ser.write("FINISHED\n".encode())
         
-    print("All requested patterns completed (or stopped).")
+    logger.info("All requested patterns completed (or stopped)")
 
 def reset_theta():
     """Reset theta on the Arduino."""
+    logger.debug("Resetting theta on Arduino")
     with serial_manager.serial_lock:
         serial_manager.ser.write("RESET_THETA\n".encode())
         while True:
             with serial_manager.serial_lock:
                 if serial_manager.ser.in_waiting > 0:
                     response = serial_manager.ser.readline().decode().strip()
-                    print(f"Arduino response: {response}")
+                    logger.debug(f"Arduino response: {response}")
                     if response == "THETA_RESET":
-                        print("Theta successfully reset.")
+                        logger.info("Theta successfully reset.")
                         break
             time.sleep(0.5)
 

dune_weaver_flask/modules/core/playlist_manager.py

@@ -1,36 +1,48 @@
 import json
 import os
 import threading
+import logging
 from dune_weaver_flask.modules.core import pattern_manager
 
+# Configure logging
+logger = logging.getLogger(__name__)
+
 # Global state
 PLAYLISTS_FILE = os.path.join(os.getcwd(), "playlists.json")
 
 # Ensure the file exists and contains at least an empty JSON object
 if not os.path.exists(PLAYLISTS_FILE):
+    logger.info(f"Creating new playlists file at {PLAYLISTS_FILE}")
     with open(PLAYLISTS_FILE, "w") as f:
         json.dump({}, f, indent=2)
 
 def load_playlists():
     """Load the entire playlists dictionary from the JSON file."""
     with open(PLAYLISTS_FILE, "r") as f:
-        return json.load(f)
+        playlists = json.load(f)
+        logger.debug(f"Loaded {len(playlists)} playlists")
+        return playlists
 
 def save_playlists(playlists_dict):
     """Save the entire playlists dictionary back to the JSON file."""
+    logger.debug(f"Saving {len(playlists_dict)} playlists to file")
     with open(PLAYLISTS_FILE, "w") as f:
         json.dump(playlists_dict, f, indent=2)
 
 def list_all_playlists():
     """Returns a list of all playlist names."""
     playlists_dict = load_playlists()
-    return list(playlists_dict.keys())
+    playlist_names = list(playlists_dict.keys())
+    logger.debug(f"Found {len(playlist_names)} playlists")
+    return playlist_names
 
 def get_playlist(playlist_name):
     """Get a specific playlist by name."""
     playlists_dict = load_playlists()
     if playlist_name not in playlists_dict:
+        logger.warning(f"Playlist not found: {playlist_name}")
         return None
+    logger.debug(f"Retrieved playlist: {playlist_name}")
     return {
         "name": playlist_name,
         "files": playlists_dict[playlist_name]
@@ -41,43 +53,52 @@ def create_playlist(playlist_name, files):
     playlists_dict = load_playlists()
     playlists_dict[playlist_name] = files
     save_playlists(playlists_dict)
+    logger.info(f"Created/updated playlist '{playlist_name}' with {len(files)} files")
     return True
 
 def modify_playlist(playlist_name, files):
     """Modify an existing playlist."""
+    logger.info(f"Modifying playlist '{playlist_name}' with {len(files)} files")
     return create_playlist(playlist_name, files)
 
 def delete_playlist(playlist_name):
     """Delete a playlist."""
     playlists_dict = load_playlists()
     if playlist_name not in playlists_dict:
+        logger.warning(f"Cannot delete non-existent playlist: {playlist_name}")
         return False
     del playlists_dict[playlist_name]
     save_playlists(playlists_dict)
+    logger.info(f"Deleted playlist: {playlist_name}")
     return True
 
 def add_to_playlist(playlist_name, pattern):
     """Add a pattern to an existing playlist."""
     playlists_dict = load_playlists()
     if playlist_name not in playlists_dict:
+        logger.warning(f"Cannot add to non-existent playlist: {playlist_name}")
         return False
     playlists_dict[playlist_name].append(pattern)
     save_playlists(playlists_dict)
+    logger.info(f"Added pattern '{pattern}' to playlist '{playlist_name}'")
     return True
 
 def run_playlist(playlist_name, pause_time=0, clear_pattern=None, run_mode="single", shuffle=False, schedule_hours=None):
     """Run a playlist with the given options."""
     playlists = load_playlists()
     if playlist_name not in playlists:
+        logger.error(f"Cannot run non-existent playlist: {playlist_name}")
         return False, "Playlist not found"
 
     file_paths = playlists[playlist_name]
     file_paths = [os.path.join(pattern_manager.THETA_RHO_DIR, file) for file in file_paths]
 
     if not file_paths:
+        logger.warning(f"Cannot run empty playlist: {playlist_name}")
         return False, "Playlist is empty"
 
     try:
+        logger.info(f"Starting playlist '{playlist_name}' with mode={run_mode}, shuffle={shuffle}")
         threading.Thread(
             target=pattern_manager.run_theta_rho_files,
             args=(file_paths,),
@@ -92,4 +113,5 @@ def run_playlist(playlist_name, pause_time=0, clear_pattern=None, run_mode="sing
         ).start()
         return True, f"Playlist '{playlist_name}' is now running."
     except Exception as e:
+        logger.error(f"Failed to run playlist '{playlist_name}': {str(e)}")
         return False, str(e)

dune_weaver_flask/modules/firmware/firmware_manager.py

@@ -1,7 +1,11 @@
 import os
 import subprocess
+import logging
 from ..serial import serial_manager
 
+# Configure logging
+logger = logging.getLogger(__name__)
+
 # Global state
 MOTOR_TYPE_MAPPING = {
     "TMC2209": "./firmware/arduino_code_TMC2209/arduino_code_TMC2209.ino",
@@ -17,6 +21,7 @@ def get_ino_firmware_details(ino_file_path):
             raise ValueError("Invalid path: ino_file_path is None or empty.")
 
         firmware_details = {"version": None, "motorType": None}
+        logger.debug(f"Reading firmware details from {ino_file_path}")
 
         with open(ino_file_path, "r") as file:
             for line in file:
@@ -33,22 +38,23 @@ def get_ino_firmware_details(ino_file_path):
                         firmware_details["motorType"] = line[start:end]
 
         if not firmware_details["version"]:
-            print(f"Firmware version not found in file: {ino_file_path}")
+            logger.warning(f"Firmware version not found in file: {ino_file_path}")
         if not firmware_details["motorType"]:
-            print(f"Motor type not found in file: {ino_file_path}")
+            logger.warning(f"Motor type not found in file: {ino_file_path}")
 
         return firmware_details if any(firmware_details.values()) else None
 
     except FileNotFoundError:
-        print(f"File not found: {ino_file_path}")
+        logger.error(f"File not found: {ino_file_path}")
         return None
     except Exception as e:
-        print(f"Error reading .ino file: {str(e)}")
+        logger.error(f"Error reading .ino file: {str(e)}")
         return None
 
 def check_git_updates():
     """Check for available Git updates."""
     try:
+        logger.debug("Checking for Git updates")
         subprocess.run(["git", "fetch", "--tags", "--force"], check=True)
         latest_remote_tag = subprocess.check_output(
             ["git", "describe", "--tags", "--abbrev=0", "origin/main"]
@@ -73,6 +79,7 @@ def check_git_updates():
                         break
 
         updates_available = latest_remote_tag != latest_local_tag
+        logger.info(f"Updates available: {updates_available}, {tag_behind_count} versions behind")
 
         return {
             "updates_available": updates_available,
@@ -81,7 +88,7 @@ def check_git_updates():
             "latest_local_tag": latest_local_tag,
         }
     except subprocess.CalledProcessError as e:
-        print(f"Error checking Git updates: {e}")
+        logger.error(f"Error checking Git updates: {e}")
         return {
             "updates_available": False,
             "tag_behind_count": 0,
@@ -92,12 +99,14 @@ def check_git_updates():
 def update_software():
     """Update the software to the latest version."""
     error_log = []
+    logger.info("Starting software update process")
 
     def run_command(command, error_message):
         try:
+            logger.debug(f"Running command: {' '.join(command)}")
             subprocess.run(command, check=True)
         except subprocess.CalledProcessError as e:
-            print(f"{error_message}: {e}")
+            logger.error(f"{error_message}: {e}")
             error_log.append(error_message)
 
     try:
@@ -105,9 +114,12 @@ def update_software():
         latest_remote_tag = subprocess.check_output(
             ["git", "describe", "--tags", "--abbrev=0", "origin/main"]
         ).strip().decode()
+        logger.info(f"Latest remote tag: {latest_remote_tag}")
     except subprocess.CalledProcessError as e:
-        error_log.append(f"Failed to fetch tags or get latest remote tag: {e}")
-        return False, "Failed to fetch tags or determine the latest version.", error_log
+        error_msg = f"Failed to fetch tags or get latest remote tag: {e}"
+        logger.error(error_msg)
+        error_log.append(error_msg)
+        return False, error_msg, error_log
 
     run_command(["git", "checkout", latest_remote_tag, '--force'], f"Failed to checkout version {latest_remote_tag}")
     run_command(["docker", "compose", "pull"], "Failed to fetch Docker containers")
@@ -119,8 +131,10 @@ def update_software():
         update_status["updates_available"] is False
         and update_status["latest_local_tag"] == update_status["latest_remote_tag"]
     ):
+        logger.info("Software update completed successfully")
         return True, None, None
     else:
+        logger.error("Software update incomplete")
         return False, "Update incomplete", error_log
 
 def get_firmware_info(motor_type=None):
@@ -177,18 +191,22 @@ def get_firmware_info(motor_type=None):
 def flash_firmware(motor_type):
     """Flash firmware for the specified motor type."""
     if not motor_type or motor_type not in MOTOR_TYPE_MAPPING:
+        logger.error(f"Invalid or missing motor type: {motor_type}")
         return False, "Invalid or missing motor type"
 
     if not serial_manager.is_connected():
+        logger.error("No device connected or connection lost")
         return False, "No device connected or connection lost"
 
     try:
         ino_file_path = MOTOR_TYPE_MAPPING[motor_type]
         hex_file_path = f"{ino_file_path}.hex"
         bin_file_path = f"{ino_file_path}.bin"
+        logger.info(f"Flashing firmware for motor type: {motor_type}")
 
         if motor_type.lower() in ["esp32", "esp32_tmc2209"]:
             if not os.path.exists(bin_file_path):
+                logger.error(f"Firmware binary not found: {bin_file_path}")
                 return False, f"Firmware binary not found: {bin_file_path}"
 
             flash_command = [
@@ -200,6 +218,7 @@ def flash_firmware(motor_type):
             ]
         else:
             if not os.path.exists(hex_file_path):
+                logger.error(f"Hex file not found: {hex_file_path}")
                 return False, f"Hex file not found: {hex_file_path}"
 
             flash_command = [
@@ -213,10 +232,14 @@ def flash_firmware(motor_type):
                 "-U", f"flash:w:{hex_file_path}:i"
             ]
 
+        logger.debug(f"Running flash command: {' '.join(flash_command)}")
         flash_process = subprocess.run(flash_command, capture_output=True, text=True)
         if flash_process.returncode != 0:
+            logger.error(f"Firmware flash failed: {flash_process.stderr}")
             return False, flash_process.stderr
 
+        logger.info("Firmware flashed successfully")
         return True, "Firmware flashed successfully"
     except Exception as e:
+        logger.error(f"Error during firmware flash: {str(e)}")
         return False, str(e)

dune_weaver_flask/modules/serial/serial_manager.py

@@ -2,6 +2,10 @@ import serial
 import serial.tools.list_ports
 import threading
 import time
+import logging
+
+# Configure logging
+logger = logging.getLogger(__name__)
 
 # Global state
 ser = None
@@ -17,7 +21,9 @@ firmware_version = 'Unknown'
 def list_serial_ports():
     """Return a list of available serial ports."""
     ports = serial.tools.list_ports.comports()
-    return [port.device for port in ports if port.device not in IGNORE_PORTS]
+    available_ports = [port.device for port in ports if port.device not in IGNORE_PORTS]
+    logger.debug(f"Available serial ports: {available_ports}")
+    return available_ports
 
 def connect_to_serial(port=None, baudrate=115200):
     """Automatically connect to the first available serial port or a specified port."""
@@ -26,7 +32,7 @@ def connect_to_serial(port=None, baudrate=115200):
         if port is None:
             ports = list_serial_ports()
             if not ports:
-                print("No serial port connected")
+                logger.warning("No serial port connected")
                 return False
             port = ports[0]  # Auto-select the first available port
 
@@ -36,13 +42,13 @@ def connect_to_serial(port=None, baudrate=115200):
             ser = serial.Serial(port, baudrate, timeout=2)
             ser_port = port
 
-        print(f"Connected to serial port: {port}")
+        logger.info(f"Connected to serial port: {port}")
         time.sleep(2)  # Allow time for the connection to establish
 
         # Read initial startup messages from Arduino
         while ser.in_waiting > 0:
             line = ser.readline().decode().strip()
-            print(f"Arduino: {line}")
+            logger.debug(f"Arduino: {line}")
 
             # Store the device details based on the expected messages
             if "Table:" in line:
@@ -52,27 +58,29 @@ def connect_to_serial(port=None, baudrate=115200):
             elif "Version:" in line:
                 firmware_version = line.replace("Version: ", "").strip()
 
-        print(f"Detected Table: {arduino_table_name or 'Unknown'}")
-        print(f"Detected Drivers: {arduino_driver_type or 'Unknown'}")
+        logger.info(f"Detected Table: {arduino_table_name or 'Unknown'}")
+        logger.info(f"Detected Drivers: {arduino_driver_type or 'Unknown'}")
 
         return True
     except serial.SerialException as e:
-        print(f"Failed to connect to serial port {port}: {e}")
+        logger.error(f"Failed to connect to serial port {port}: {e}")
         ser_port = None
 
-    print("Max retries reached. Could not connect to a serial port.")
+    logger.error("Max retries reached. Could not connect to a serial port.")
     return False
 
 def disconnect_serial():
     """Disconnect the current serial connection."""
     global ser, ser_port
     if ser and ser.is_open:
+        logger.info("Disconnecting serial connection")
         ser.close()
         ser = None
     ser_port = None
 
 def restart_serial(port, baudrate=115200):
     """Restart the serial connection."""
+    logger.info(f"Restarting serial connection on port {port}")
     disconnect_serial()
     return connect_to_serial(port, baudrate)
 
@@ -81,21 +89,22 @@ def send_coordinate_batch(coordinates):
     batch_str = ";".join(f"{theta:.5f},{rho:.5f}" for theta, rho in coordinates) + ";\n"
     with serial_lock:
         ser.write(batch_str.encode())
+        logger.debug(f"Sent coordinate batch: {batch_str.strip()}")
 
 def send_command(command):
     """Send a single command to the Arduino."""
     with serial_lock:
         ser.write(f"{command}\n".encode())
-        print(f"Sent: {command}")
+        logger.debug(f"Sent command: {command}")
 
         # Wait for "R" acknowledgment from Arduino
         while True:
             with serial_lock:
                 if ser.in_waiting > 0:
                     response = ser.readline().decode().strip()
-                    print(f"Arduino response: {response}")
+                    logger.debug(f"Arduino response: {response}")
                     if response == "R":
-                        print("Command execution completed.")
+                        logger.debug("Command execution completed")
                         break
 
 def is_connected():