diff --git a/controller/lib/admin.py b/controller/lib/admin.py index 6e4c95ee..ffbafe17 100644 --- a/controller/lib/admin.py +++ b/controller/lib/admin.py @@ -6,6 +6,7 @@ Migrated from wrolpi/admin.py - provides system control functions. import asyncio import enum +import logging import subprocess from pathlib import Path @@ -13,6 +14,8 @@ import yaml from controller.lib.config import is_docker_mode, get_config_value, get_media_directory +logger = logging.getLogger(__name__) + # Constants - use controller's own config instead of wrolpi module DEFAULT_CPU_FREQUENCY = get_config_value('throttle.default_governor', 'ondemand') @@ -164,6 +167,7 @@ def enable_hotspot() -> dict: ) # Create hotspot using NetworkManager + logger.info("Enabling hotspot on %s with SSID %s", device, ssid) result = subprocess.run( [ "nmcli", "device", "wifi", "hotspot", @@ -177,15 +181,20 @@ def enable_hotspot() -> dict: ) if result.returncode == 0: + logger.info("Hotspot enabled successfully on %s", device) return {"success": True, "ssid": ssid, "device": device} else: + logger.warning("Failed to enable hotspot: %s", result.stderr.strip()) return {"success": False, "error": result.stderr.strip() or "Unknown error"} except subprocess.TimeoutExpired: + logger.warning("Timeout enabling hotspot on %s", device) return {"success": False, "error": "Timeout enabling hotspot"} except FileNotFoundError: + logger.warning("nmcli not found, cannot enable hotspot") return {"success": False, "error": "nmcli not found"} except subprocess.SubprocessError as e: + logger.warning("Failed to enable hotspot: %s", e) return {"success": False, "error": str(e)} @@ -199,6 +208,7 @@ def disable_hotspot() -> dict: if is_docker_mode(): return {"success": False, "error": "Not available in Docker mode"} + logger.info("Disabling hotspot") try: # Turn off the radio to disconnect hotspot result = subprocess.run( @@ -209,13 +219,17 @@ def disable_hotspot() -> dict: ) # Success even if already off + logger.info("Hotspot disabled successfully") return {"success": True} except subprocess.TimeoutExpired: + logger.warning("Timeout disabling hotspot") return {"success": False, "error": "Timeout disabling hotspot"} except FileNotFoundError: + logger.warning("nmcli not found, cannot disable hotspot") return {"success": False, "error": "nmcli not found"} except subprocess.SubprocessError as e: + logger.warning("Failed to disable hotspot: %s", e) return {"success": False, "error": str(e)} @@ -310,6 +324,7 @@ def enable_throttle() -> dict: if is_docker_mode(): return {"success": False, "error": "Not available in Docker mode"} + logger.info("Enabling CPU throttle (powersave)") try: # Try cpufreq-set first result = subprocess.run( @@ -320,8 +335,10 @@ def enable_throttle() -> dict: ) if result.returncode == 0: + logger.info("CPU throttle enabled (powersave)") return {"success": True, "governor": "powersave"} else: + logger.warning("Failed to enable CPU throttle: %s", result.stderr.strip()) return {"success": False, "error": result.stderr.strip() or "Unknown error"} except FileNotFoundError: @@ -329,12 +346,16 @@ def enable_throttle() -> dict: try: for cpu_path in Path("/sys/devices/system/cpu/").glob("cpu[0-9]*/cpufreq/scaling_governor"): cpu_path.write_text("powersave") + logger.info("CPU throttle enabled (powersave) via sysfs") return {"success": True, "governor": "powersave"} except IOError as e: + logger.warning("Failed to enable CPU throttle via sysfs: %s", e) return {"success": False, "error": str(e)} except subprocess.TimeoutExpired: + logger.warning("Timeout enabling CPU throttle") return {"success": False, "error": "Timeout enabling throttle"} except subprocess.SubprocessError as e: + logger.warning("Failed to enable CPU throttle: %s", e) return {"success": False, "error": str(e)} @@ -350,6 +371,7 @@ def disable_throttle() -> dict: default_governor = DEFAULT_CPU_FREQUENCY + logger.info("Disabling CPU throttle (setting governor to %s)", default_governor) try: result = subprocess.run( ["cpufreq-set", "-g", default_governor], @@ -359,8 +381,10 @@ def disable_throttle() -> dict: ) if result.returncode == 0: + logger.info("CPU throttle disabled (governor: %s)", default_governor) return {"success": True, "governor": default_governor} else: + logger.warning("Failed to disable CPU throttle: %s", result.stderr.strip()) return {"success": False, "error": result.stderr.strip() or "Unknown error"} except FileNotFoundError: @@ -368,12 +392,16 @@ def disable_throttle() -> dict: try: for cpu_path in Path("/sys/devices/system/cpu/").glob("cpu[0-9]*/cpufreq/scaling_governor"): cpu_path.write_text(default_governor) + logger.info("CPU throttle disabled (governor: %s) via sysfs", default_governor) return {"success": True, "governor": default_governor} except IOError as e: + logger.warning("Failed to disable CPU throttle via sysfs: %s", e) return {"success": False, "error": str(e)} except subprocess.TimeoutExpired: + logger.warning("Timeout disabling CPU throttle") return {"success": False, "error": "Timeout disabling throttle"} except subprocess.SubprocessError as e: + logger.warning("Failed to disable CPU throttle: %s", e) return {"success": False, "error": str(e)} @@ -405,8 +433,10 @@ def shutdown_system(delay: int = 10) -> dict: import threading thread = threading.Thread(target=_delayed_shutdown, daemon=True) thread.start() + logger.info("System shutdown scheduled in %d seconds", delay) return {"success": True, "message": f"System shutting down in {delay} seconds"} except Exception as e: + logger.warning("Failed to schedule system shutdown: %s", e) return {"success": False, "error": str(e)} @@ -438,8 +468,10 @@ def reboot_system(delay: int = 10) -> dict: import threading thread = threading.Thread(target=_delayed_reboot, daemon=True) thread.start() + logger.info("System reboot scheduled in %d seconds", delay) return {"success": True, "message": f"System rebooting in {delay} seconds"} except Exception as e: + logger.warning("Failed to schedule system reboot: %s", e) return {"success": False, "error": str(e)} @@ -471,7 +503,9 @@ async def restart_all_services() -> dict: results = {} + logger.info("Restarting all WROLPi services") for service in services_to_restart: + logger.info("Restarting service %s", service) try: result = subprocess.run( ["systemctl", "restart", service], @@ -483,11 +517,18 @@ async def restart_all_services() -> dict: "success": result.returncode == 0, "error": result.stderr.strip() if result.returncode != 0 else None, } + if result.returncode == 0: + logger.info("Service %s restarted successfully", service) + else: + logger.warning("Failed to restart service %s: %s", service, result.stderr.strip()) except subprocess.TimeoutExpired: + logger.warning("Timeout restarting service %s", service) results[service] = {"success": False, "error": "Timeout"} except FileNotFoundError: + logger.warning("systemctl not found while restarting %s", service) results[service] = {"success": False, "error": "systemctl not found"} except Exception as e: + logger.warning("Failed to restart service %s: %s", service, e) results[service] = {"success": False, "error": str(e)} # Schedule Controller self-restart after response is sent @@ -581,6 +622,7 @@ def set_timezone(timezone: str) -> dict: if not timezone or not timezone.strip(): return {"success": False, "timezone": None, "error": "Timezone must not be empty"} + logger.info("Setting system timezone to %s", timezone) try: result = subprocess.run( ["timedatectl", "set-timezone", timezone], @@ -590,15 +632,20 @@ def set_timezone(timezone: str) -> dict: ) if result.returncode == 0: + logger.info("System timezone set to %s", timezone) return {"success": True, "timezone": timezone, "error": None} else: + logger.warning("Failed to set timezone to %s: %s", timezone, result.stderr.strip()) return {"success": False, "timezone": None, "error": result.stderr.strip() or "Unknown error"} except FileNotFoundError: + logger.warning("timedatectl not found, cannot set timezone") return {"success": False, "timezone": None, "error": "timedatectl not found"} except subprocess.TimeoutExpired: + logger.warning("Timeout setting timezone to %s", timezone) return {"success": False, "timezone": None, "error": "Timeout setting timezone"} except subprocess.SubprocessError as e: + logger.warning("Failed to set timezone: %s", e) return {"success": False, "timezone": None, "error": str(e)} @@ -618,7 +665,7 @@ def apply_timezone_from_config(): with open(config_path) as f: config = yaml.safe_load(f) or {} except (IOError, yaml.YAMLError) as e: - print(f"Warning: Failed to read wrolpi.yaml for timezone: {e}") + logger.warning("Failed to read wrolpi.yaml for timezone: %s", e) return timezone = config.get('timezone') @@ -627,6 +674,6 @@ def apply_timezone_from_config(): result = set_timezone(timezone) if result.get('success'): - print(f"Applied system timezone: {timezone}") + logger.info("Applied system timezone from config: %s", timezone) else: - print(f"Warning: Failed to apply system timezone '{timezone}': {result.get('error')}") + logger.warning("Failed to apply system timezone '%s': %s", timezone, result.get('error')) diff --git a/controller/lib/config.py b/controller/lib/config.py index b0271571..43eb090b 100644 --- a/controller/lib/config.py +++ b/controller/lib/config.py @@ -6,6 +6,7 @@ from controller.yaml on the WROLPi drive after it's mounted. """ import copy +import logging import os from pathlib import Path from typing import Any @@ -14,6 +15,8 @@ import yaml from controller.defaults import DEFAULT_CONFIG +logger = logging.getLogger(__name__) + # Path to config file on the WROLPi drive CONFIG_PATH_ON_DRIVE = Path("/media/wrolpi/config/controller.yaml") @@ -91,7 +94,7 @@ def reload_config_from_drive() -> bool: drive_config = yaml.safe_load(f) or {} except (IOError, yaml.YAMLError) as e: # Failed to load - keep defaults - print(f"Warning: Failed to load controller.yaml: {e}") + logger.warning("Failed to load controller.yaml: %s", e) return False # Deep merge: drive_config overrides defaults diff --git a/controller/lib/disks.py b/controller/lib/disks.py index 9580d470..3504fed4 100644 --- a/controller/lib/disks.py +++ b/controller/lib/disks.py @@ -6,6 +6,7 @@ Provides disk detection, mounting, and WROLPi drive identification. import grp import json +import logging import pwd import subprocess import tempfile @@ -15,6 +16,8 @@ from typing import Optional from controller.lib.config import is_docker_mode +logger = logging.getLogger(__name__) + SUPPORTED_FILESYSTEMS = {"ext4", "btrfs", "vfat", "exfat"} @@ -180,13 +183,17 @@ def mount_drive( cmd.extend(["-o", options]) cmd.extend([device, mount_point]) + logger.info("Mounting %s to %s (fstype=%s)", device, mount_point, fstype) try: result = subprocess.run(cmd, capture_output=True, text=True, timeout=30) if result.returncode == 0: + logger.info("Mounted %s to %s successfully", device, mount_point) return {"success": True, "mount_point": mount_point} else: + logger.warning("Failed to mount %s to %s: %s", device, mount_point, result.stderr.strip()) return {"success": False, "error": result.stderr.strip()} except subprocess.TimeoutExpired: + logger.warning("Mount timed out for %s to %s", device, mount_point) return {"success": False, "error": "Mount timed out"} @@ -217,13 +224,17 @@ def unmount_drive(mount_point: str, lazy: bool = False) -> dict: cmd.append("-l") cmd.append(mount_point) + logger.info("Unmounting %s (lazy=%s)", mount_point, lazy) try: result = subprocess.run(cmd, capture_output=True, text=True, timeout=30) if result.returncode == 0: + logger.info("Unmounted %s successfully", mount_point) return {"success": True, "mount_point": mount_point} else: + logger.warning("Failed to unmount %s: %s", mount_point, result.stderr.strip()) return {"success": False, "error": result.stderr.strip()} except subprocess.TimeoutExpired: + logger.warning("Unmount timed out for %s", mount_point) return {"success": False, "error": "Unmount timed out"} diff --git a/controller/lib/docker_services.py b/controller/lib/docker_services.py index 8908de58..ce4736db 100644 --- a/controller/lib/docker_services.py +++ b/controller/lib/docker_services.py @@ -4,10 +4,13 @@ Docker container management for WROLPi Controller. Used when running in Docker mode instead of systemd. """ +import logging import os from controller.lib.config import is_docker_mode +logger = logging.getLogger(__name__) + # Import docker only if available (optional dependency) try: import docker @@ -173,15 +176,19 @@ def start_container(name: str) -> dict: if not can_manage_containers(): return {"success": False, "error": "Docker management not available"} + logger.info("Starting container %s", name) try: client = _get_client() container_name = _get_container_name(name) container = client.containers.get(container_name) container.start() + logger.info("Container %s started successfully", name) return {"success": True, "service": name, "action": "start"} except NotFound: + logger.warning("Container not found: %s", name) return {"success": False, "error": f"Container not found: {name}"} except Exception as e: + logger.warning("Failed to start container %s: %s", name, e) return {"success": False, "error": str(e)} @@ -190,15 +197,19 @@ def stop_container(name: str) -> dict: if not can_manage_containers(): return {"success": False, "error": "Docker management not available"} + logger.info("Stopping container %s", name) try: client = _get_client() container_name = _get_container_name(name) container = client.containers.get(container_name) container.stop(timeout=30) + logger.info("Container %s stopped successfully", name) return {"success": True, "service": name, "action": "stop"} except NotFound: + logger.warning("Container not found: %s", name) return {"success": False, "error": f"Container not found: {name}"} except Exception as e: + logger.warning("Failed to stop container %s: %s", name, e) return {"success": False, "error": str(e)} @@ -207,15 +218,19 @@ def restart_container(name: str) -> dict: if not can_manage_containers(): return {"success": False, "error": "Docker management not available"} + logger.info("Restarting container %s", name) try: client = _get_client() container_name = _get_container_name(name) container = client.containers.get(container_name) container.restart(timeout=30) + logger.info("Container %s restarted successfully", name) return {"success": True, "service": name, "action": "restart"} except NotFound: + logger.warning("Container not found: %s", name) return {"success": False, "error": f"Container not found: {name}"} except Exception as e: + logger.warning("Failed to restart container %s: %s", name, e) return {"success": False, "error": str(e)} diff --git a/controller/lib/fstab.py b/controller/lib/fstab.py index 07b5f80f..54c17ac0 100644 --- a/controller/lib/fstab.py +++ b/controller/lib/fstab.py @@ -4,6 +4,7 @@ fstab management for WROLPi Controller. Provides persistent mount configuration via /etc/fstab. """ +import logging import shutil import subprocess from datetime import datetime @@ -12,6 +13,8 @@ from pathlib import Path from controller.lib.disks import get_uuid, get_wrolpi_uid_gid, validate_mount_point from controller.lib.wrol_mode import require_normal_mode +logger = logging.getLogger(__name__) + FSTAB_PATH = Path("/etc/fstab") @@ -24,6 +27,7 @@ def backup_fstab() -> Path: # Also keep a known backup location for easy recovery shutil.copy(FSTAB_PATH, Path("/etc/fstab.wrolpi.backup")) + logger.info("Created fstab backup at %s", backup_path) return backup_path @@ -186,6 +190,7 @@ def add_fstab_entry( # Reload systemd subprocess.run(["systemctl", "daemon-reload"], capture_output=True) + logger.info("Added fstab entry: %s -> %s (fstype=%s)", device_spec, mount_point, fstype) return { "success": True, "device": device_spec, @@ -241,6 +246,7 @@ def remove_fstab_entry(mount_point: str) -> dict: subprocess.run(["systemctl", "daemon-reload"], capture_output=True) + logger.info("Removed fstab entry for %s", mount_point) return {"success": True, "mount_point": mount_point} diff --git a/controller/lib/scripts.py b/controller/lib/scripts.py index f168ab74..cdddf05d 100644 --- a/controller/lib/scripts.py +++ b/controller/lib/scripts.py @@ -5,12 +5,15 @@ Manages maintenance scripts that run as systemd services (like repair.sh). Uses systemd oneshot services for process survival across controller restarts. """ +import logging import subprocess from datetime import datetime from typing import Optional from controller.lib.config import is_docker_mode +logger = logging.getLogger(__name__) + # Available scripts with their configurations # Parameters define inputs that scripts accept: # - name: Parameter name (used as env var name, e.g., "branch" -> "BRANCH=value") @@ -244,6 +247,7 @@ def start_script(name: str, params: Optional[dict] = None) -> dict: "error": f"Failed to write script config: {e}", } + logger.info("Starting script '%s' (service: %s)", name, service) try: # Start the service (non-blocking via Popen) # No sudo needed - Controller runs as root @@ -253,16 +257,19 @@ def start_script(name: str, params: Optional[dict] = None) -> dict: stderr=subprocess.DEVNULL, stdin=subprocess.DEVNULL, ) + logger.info("Script '%s' started successfully", name) return { "success": True, "message": f"Script '{name}' started", } except FileNotFoundError: + logger.warning("systemctl not found, cannot start script '%s'", name) return { "success": False, "error": "systemctl not found", } except subprocess.SubprocessError as e: + logger.warning("Failed to start script '%s': %s", name, e) return { "success": False, "error": str(e), diff --git a/controller/lib/status_worker.py b/controller/lib/status_worker.py index 424359a5..934b0790 100644 --- a/controller/lib/status_worker.py +++ b/controller/lib/status_worker.py @@ -6,10 +6,13 @@ for O(1) response times on API endpoints. """ import asyncio +import logging import multiprocessing from datetime import datetime from typing import Optional +logger = logging.getLogger(__name__) + from controller.lib.status import ( get_cpu_status, get_disk_bandwidth_status, @@ -109,7 +112,7 @@ async def status_worker_loop(app, base_sleep: float = 5.0): app: FastAPI application instance base_sleep: Base sleep interval in seconds (default 5s) """ - print("Status worker started") + logger.info("Status worker started") while True: try: @@ -123,10 +126,10 @@ async def status_worker_loop(app, base_sleep: float = 5.0): sleep_time = get_adaptive_sleep(status.get("load_stats"), base_sleep) except asyncio.CancelledError: - print("Status worker cancelled") + logger.info("Status worker cancelled") raise except Exception as e: - print(f"Status worker error: {e}") + logger.error("Status worker error: %s", e) sleep_time = base_sleep await asyncio.sleep(sleep_time) diff --git a/controller/lib/systemd.py b/controller/lib/systemd.py index 4b55fe65..13793f7a 100644 --- a/controller/lib/systemd.py +++ b/controller/lib/systemd.py @@ -4,11 +4,14 @@ Systemd service management for WROLPi Controller. Provides start/stop/restart/status/logs for systemd services. """ +import logging import subprocess from typing import Optional from controller.lib.config import get_config +logger = logging.getLogger(__name__) + def get_managed_services() -> list[dict]: """ @@ -300,7 +303,12 @@ def start_service(name: str) -> dict: systemd_name = _get_systemd_name(name) if not systemd_name: return {"success": False, "error": f"Unknown service: {name}"} + logger.info("Starting service %s (systemd: %s)", name, systemd_name) result = _run_systemctl("start", systemd_name) + if result["success"]: + logger.info("Service %s started successfully", name) + else: + logger.warning("Failed to start service %s: %s", name, result.get("error")) return { "success": result["success"], @@ -323,7 +331,12 @@ def stop_service(name: str) -> dict: systemd_name = _get_systemd_name(name) if not systemd_name: return {"success": False, "error": f"Unknown service: {name}"} + logger.info("Stopping service %s (systemd: %s)", name, systemd_name) result = _run_systemctl("stop", systemd_name) + if result["success"]: + logger.info("Service %s stopped successfully", name) + else: + logger.warning("Failed to stop service %s: %s", name, result.get("error")) return { "success": result["success"], @@ -347,11 +360,14 @@ def restart_service(name: str) -> dict: if not systemd_name: return {"success": False, "error": f"Unknown service: {name}"} + logger.info("Restarting service %s (systemd: %s)", name, systemd_name) + # Special handling for self-restart: use Popen to avoid blocking # (the process will be killed before subprocess.run can return) if systemd_name == "wrolpi-controller": try: subprocess.Popen(["systemctl", "restart", systemd_name]) + logger.info("Service %s self-restart initiated", name) return { "success": True, "service": name, @@ -359,6 +375,7 @@ def restart_service(name: str) -> dict: "pending": True, } except Exception as e: + logger.warning("Failed to restart service %s: %s", name, e) return { "success": False, "service": name, @@ -367,6 +384,10 @@ def restart_service(name: str) -> dict: } result = _run_systemctl("restart", systemd_name) + if result["success"]: + logger.info("Service %s restarted successfully", name) + else: + logger.warning("Failed to restart service %s: %s", name, result.get("error")) return { "success": result["success"], @@ -389,7 +410,12 @@ def enable_service(name: str) -> dict: systemd_name = _get_systemd_name(name) if not systemd_name: return {"success": False, "error": f"Unknown service: {name}"} + logger.info("Enabling service %s (systemd: %s)", name, systemd_name) result = _run_systemctl("enable", systemd_name) + if result["success"]: + logger.info("Service %s enabled successfully", name) + else: + logger.warning("Failed to enable service %s: %s", name, result.get("error")) return { "success": result["success"], @@ -412,7 +438,12 @@ def disable_service(name: str) -> dict: systemd_name = _get_systemd_name(name) if not systemd_name: return {"success": False, "error": f"Unknown service: {name}"} + logger.info("Disabling service %s (systemd: %s)", name, systemd_name) result = _run_systemctl("disable", systemd_name) + if result["success"]: + logger.info("Service %s disabled successfully", name) + else: + logger.warning("Failed to disable service %s: %s", name, result.get("error")) return { "success": result["success"], diff --git a/controller/main.py b/controller/main.py index 8f672bda..da3aec13 100644 --- a/controller/main.py +++ b/controller/main.py @@ -10,9 +10,13 @@ The Controller provides: """ import asyncio +import logging from contextlib import asynccontextmanager from pathlib import Path +logging.basicConfig(level=logging.INFO, format='%(asctime)s %(name)s %(levelname)s %(message)s') +logger = logging.getLogger(__name__) + from fastapi import FastAPI, Request from fastapi.responses import HTMLResponse from fastapi.templating import Jinja2Templates @@ -59,21 +63,21 @@ async def lifespan(app: FastAPI): Runs on startup and shutdown. """ # Startup - print(f"WROLPi Controller v{__version__} starting...") - print(f"Docker mode: {is_docker_mode()}") + logger.info("WROLPi Controller v%s starting...", __version__) + logger.info("Docker mode: %s", is_docker_mode()) # Try to load config from drive if mounted if is_primary_drive_mounted(): if reload_config_from_drive(): - print("Loaded configuration from drive") + logger.info("Loaded configuration from drive") else: - print("Using default configuration (no controller.yaml found)") + logger.info("Using default configuration (no controller.yaml found)") # Apply timezone from wrolpi.yaml to the system. from controller.lib.admin import apply_timezone_from_config apply_timezone_from_config() else: - print("Primary drive not mounted - using default configuration") + logger.info("Primary drive not mounted - using default configuration") # Initialize cached status app.state.cached_status = {} @@ -84,7 +88,7 @@ async def lifespan(app: FastAPI): yield # Shutdown - print("WROLPi Controller shutting down...") + logger.info("WROLPi Controller shutting down...") status_task.cancel() try: await status_task