updated logging

2026-04-02 13:15:19 -05:00
parent 38733daffc
commit 150666d7c3
3 changed files with 134 additions and 137 deletions
--- a/app/sovran_systemsos_web/server.py
+++ b/app/sovran_systemsos_web/server.py
@@ -8,10 +8,9 @@ import os
 import socket
 import subprocess
 import urllib.request
-from typing import AsyncIterator

-from fastapi import FastAPI, HTTPException, Response
-from fastapi.responses import HTMLResponse, StreamingResponse
+from fastapi import FastAPI, HTTPException
+from fastapi.responses import HTMLResponse
 from fastapi.staticfiles import StaticFiles
 from fastapi.templating import Jinja2Templates
 from fastapi.requests import Request
@@ -26,10 +25,9 @@ FLAKE_INPUT_NAME = "Sovran_Systems"
 GITEA_API_BASE = "https://git.sovransystems.com/api/v1/repos/Sovran_Systems/Sovran_SystemsOS/commits"

 UPDATE_UNIT = "sovran-hub-update.service"
+UPDATE_LOG  = "/var/log/sovran-hub-update.log"

-REBOOT_COMMAND = [
-    "reboot",
-]
+REBOOT_COMMAND = ["reboot"]

 CATEGORY_ORDER = [
    ("infrastructure", "Infrastructure"),
@@ -58,7 +56,6 @@ app.mount(
    name="static",
 )

-# Also serve icons from the app/icons directory (set via env or adjacent folder)
 _ICONS_DIR = os.environ.get(
    "SOVRAN_HUB_ICONS",
    os.path.join(os.path.dirname(_BASE_DIR), "icons"),
@@ -141,7 +138,6 @@ def _get_internal_ip() -> str:


 def _get_external_ip() -> str:
-    # Max length 46 covers the longest valid IPv6 address (45 chars) plus a newline
    MAX_IP_LENGTH = 46
    for url in [
        "https://api.ipify.org",
@@ -184,44 +180,21 @@ def _update_result() -> str:
    return "unknown"


-def _get_update_invocation_id() -> str:
-    """Get the current InvocationID of the update unit."""
-    r = subprocess.run(
-        ["systemctl", "show", "-p", "InvocationID", "--value", UPDATE_UNIT],
-        capture_output=True, text=True,
-    )
-    return r.stdout.strip()
-
-
-def _read_journal_logs(since_cursor: str = "") -> tuple[list[str], str]:
-    """
-    Read journal logs for the update unit.
-    Returns (lines, last_cursor).
-    Uses cursors so we never miss lines even if the server restarts.
-    """
-    cmd = [
-        "journalctl", "-u", UPDATE_UNIT,
-        "--no-pager", "-o", "cat",
-        "--show-cursor",
-    ]
-    if since_cursor:
-        cmd += ["--after-cursor", since_cursor]
-    else:
-        # Only get logs from the most recent invocation
-        cmd += ["-n", "10000"]
-
-    r = subprocess.run(cmd, capture_output=True, text=True, timeout=10)
-    output = r.stdout
-
-    lines = []
-    cursor = since_cursor
-    for raw_line in output.split("\n"):
-        if raw_line.startswith("-- cursor: "):
-            cursor = raw_line[len("-- cursor: "):]
-        elif raw_line:
-            lines.append(raw_line)
-
-    return lines, cursor
+def _read_log(offset: int = 0) -> tuple[str, int]:
+    """Read the update log file from the given byte offset.
+    Returns (new_text, new_offset)."""
+    try:
+        with open(UPDATE_LOG, "rb") as f:
+            f.seek(0, 2)  # seek to end
+            size = f.tell()
+            if offset > size:
+                # Log was truncated (new run), start over
+                offset = 0
+            f.seek(offset)
+            chunk = f.read()
+            return chunk.decode(errors="replace"), offset + len(chunk)
+    except FileNotFoundError:
+        return "", 0


 # ── Routes ───────────────────────────────────────────────────────
@@ -275,7 +248,6 @@ async def api_services():


 def _get_allowed_units() -> set[str]:
-    """Return the set of unit names from the current config (whitelist)."""
    cfg = load_config()
    return {s.get("unit", "") for s in cfg.get("services", []) if s.get("unit")}

@@ -356,19 +328,19 @@ async def api_updates_run():
    """Kick off the detached update systemd unit."""
    loop = asyncio.get_event_loop()

-    # Check if already running
    running = await loop.run_in_executor(None, _update_is_active)
    if running:
        return {"ok": True, "status": "already_running"}

-    # Reset the failed state (if any) and start the unit
+    # Reset failed state if any
    await asyncio.create_subprocess_exec(
        "systemctl", "reset-failed", UPDATE_UNIT,
        stdout=asyncio.subprocess.DEVNULL,
        stderr=asyncio.subprocess.DEVNULL,
    )
+
    proc = await asyncio.create_subprocess_exec(
-        "systemctl", "start", UPDATE_UNIT,
+        "systemctl", "start", "--no-block", UPDATE_UNIT,
        stdout=asyncio.subprocess.DEVNULL,
        stderr=asyncio.subprocess.DEVNULL,
    )
@@ -378,19 +350,17 @@ async def api_updates_run():


@app.get("/api/updates/status")
-async def api_updates_status(cursor: str = ""):
-    """Poll endpoint: returns running state, result, and new journal lines."""
+async def api_updates_status(offset: int = 0):
+    """Poll endpoint: returns running state, result, and new log content."""
    loop = asyncio.get_event_loop()

    running = await loop.run_in_executor(None, _update_is_active)
    result = await loop.run_in_executor(None, _update_result)
-    lines, new_cursor = await loop.run_in_executor(
-        None, _read_journal_logs, cursor,
-    )
+    new_log, new_offset = await loop.run_in_executor(None, _read_log, offset)

    return {
        "running": running,
        "result": result,
-        "lines": lines,
-        "cursor": new_cursor,
+        "log": new_log,
+        "offset": new_offset,
    }
--- a/app/sovran_systemsos_web/static/app.js
+++ b/app/sovran_systemsos_web/static/app.js
@@ -4,7 +4,7 @@
 const POLL_INTERVAL_SERVICES = 5000;   // 5 s
 const POLL_INTERVAL_UPDATES  = 1800000; // 30 min
 const ACTION_REFRESH_DELAY   = 1500;   // 1.5 s after start/stop/restart
-const UPDATE_POLL_INTERVAL   = 2000;   // 2 s while update is running
+const UPDATE_POLL_INTERVAL   = 1500;   // 1.5 s while update is running

 const CATEGORY_ORDER = [
  "infrastructure",
@@ -21,29 +21,28 @@ const STATUS_LOADING_STATES = new Set([

 // ── State ─────────────────────────────────────────────────────────

-let _servicesCache  = [];
-let _categoryLabels = {};
-let _updateSource   = null;
-let _updateLog      = "";
+let _servicesCache   = [];
+let _categoryLabels  = {};
+let _updateLog       = "";
 let _updatePollTimer = null;
-let _updateCursor    = "";
-let _serverDownSince = 0;
+let _updateLogOffset = 0;
+let _serverWasDown   = false;

-// ── DOM refs ──────────────────────────────────────────────────────
+// ── DOM refs ────────────────────────────────────────────<EFBFBD><EFBFBD><EFBFBD>─────────

-const $tilesArea    = document.getElementById("tiles-area");
-const $updateBtn    = document.getElementById("btn-update");
-const $updateBadge  = document.getElementById("update-badge");
-const $refreshBtn   = document.getElementById("btn-refresh");
-const $internalIp   = document.getElementById("ip-internal");
-const $externalIp   = document.getElementById("ip-external");
+const $tilesArea     = document.getElementById("tiles-area");
+const $updateBtn     = document.getElementById("btn-update");
+const $updateBadge   = document.getElementById("update-badge");
+const $refreshBtn    = document.getElementById("btn-refresh");
+const $internalIp    = document.getElementById("ip-internal");
+const $externalIp    = document.getElementById("ip-external");

-const $modal        = document.getElementById("update-modal");
-const $modalSpinner = document.getElementById("modal-spinner");
-const $modalStatus  = document.getElementById("modal-status");
-const $modalLog     = document.getElementById("modal-log");
-const $btnReboot    = document.getElementById("btn-reboot");
-const $btnSave      = document.getElementById("btn-save-report");
+const $modal         = document.getElementById("update-modal");
+const $modalSpinner  = document.getElementById("modal-spinner");
+const $modalStatus   = document.getElementById("modal-status");
+const $modalLog      = document.getElementById("modal-log");
+const $btnReboot     = document.getElementById("btn-reboot");
+const $btnSave       = document.getElementById("btn-save-report");
 const $btnCloseModal = document.getElementById("btn-close-modal");

 // ── Helpers ───────────────────────────────────────────────────────
@@ -77,7 +76,6 @@ async function apiFetch(path, options = {}) {
 function buildTiles(services, categoryLabels) {
  _servicesCache = services;

-  // Group by category
  const grouped = {};
  for (const svc of services) {
    const cat = svc.category || "other";
@@ -155,7 +153,6 @@ function buildTile(svc) {
    </div>
  `;

-  // Toggle handler
  const chk = tile.querySelector(".tile-toggle");
  if (!dis) {
    chk.addEventListener("change", async (e) => {
@@ -168,7 +165,6 @@ function buildTile(svc) {
    });
  }

-  // Restart handler
  const restartBtn = tile.querySelector(".tile-restart-btn");
  if (!dis) {
    restartBtn.addEventListener("click", async () => {
@@ -265,14 +261,14 @@ async function checkUpdates() {
 function openUpdateModal() {
  if (!$modal) return;
  _updateLog = "";
-  _updateCursor = "";
-  _serverDownSince = 0;
-  if ($modalLog)    $modalLog.textContent = "";
-  if ($modalStatus) $modalStatus.textContent = "Updating…";
-  if ($modalSpinner) $modalSpinner.classList.add("spinning");
-  if ($btnReboot)   { $btnReboot.style.display   = "none"; }
-  if ($btnSave)     { $btnSave.style.display      = "none"; }
-  if ($btnCloseModal) { $btnCloseModal.disabled   = true;   }
+  _updateLogOffset = 0;
+  _serverWasDown = false;
+  if ($modalLog)      $modalLog.textContent = "";
+  if ($modalStatus)   $modalStatus.textContent = "Starting update…";
+  if ($modalSpinner)  $modalSpinner.classList.add("spinning");
+  if ($btnReboot)     { $btnReboot.style.display   = "none"; }
+  if ($btnSave)       { $btnSave.style.display      = "none"; }
+  if ($btnCloseModal) { $btnCloseModal.disabled     = true;   }

  $modal.classList.add("open");
  startUpdate();
@@ -286,18 +282,14 @@ function closeUpdateModal() {

 function appendLog(text) {
  if (!text) return;
-  _updateLog += text + "\n";
+  _updateLog += text;
  if ($modalLog) {
-    $modalLog.textContent += text + "\n";
+    $modalLog.textContent += text;
    $modalLog.scrollTop = $modalLog.scrollHeight;
  }
 }

 function startUpdate() {
-  appendLog("$ cd /etc/nixos && nix flake update && nixos-rebuild switch && flatpak update -y");
-  appendLog("");
-
-  // Trigger the systemd unit via POST
  fetch("/api/updates/run", { method: "POST" })
    .then(response => {
      if (!response.ok) {
@@ -307,19 +299,18 @@ function startUpdate() {
    })
    .then(data => {
      if (data.status === "already_running") {
-        appendLog("[Update already in progress, attaching…]");
+        appendLog("[Update already in progress, attaching…]\n\n");
      }
-      // Start polling for journal output
+      if ($modalStatus) $modalStatus.textContent = "Updating…";
      startUpdatePoll();
    })
    .catch(err => {
-      appendLog(`[Error: failed to start update — ${err}]`);
+      appendLog(`[Error: failed to start update — ${err}]\n`);
      onUpdateDone(false);
    });
 }

 function startUpdatePoll() {
-  // Poll immediately, then on interval
  pollUpdateStatus();
  _updatePollTimer = setInterval(pollUpdateStatus, UPDATE_POLL_INTERVAL);
 }
@@ -333,31 +324,22 @@ function stopUpdatePoll() {

 async function pollUpdateStatus() {
  try {
-    const data = await apiFetch(
-      `/api/updates/status?cursor=${encodeURIComponent(_updateCursor)}`
-    );
+    const data = await apiFetch(`/api/updates/status?offset=${_updateLogOffset}`);

-    // Server is back — reset the down counter
-    if (_serverDownSince > 0) {
-      appendLog("[Server reconnected, resuming…]");
-      _serverDownSince = 0;
-    }
-
-    // Append new journal lines
-    if (data.lines && data.lines.length > 0) {
-      for (const line of data.lines) {
-        appendLog(line);
-      }
-    }
-    if (data.cursor) {
-      _updateCursor = data.cursor;
-    }
-
-    // Update status text while running
-    if (data.running) {
+    // Server came back after being down
+    if (_serverWasDown) {
+      _serverWasDown = false;
      if ($modalStatus) $modalStatus.textContent = "Updating…";
-    } else {
-      // Finished
+    }
+
+    // Append any new log content
+    if (data.log) {
+      appendLog(data.log);
+    }
+    _updateLogOffset = data.offset;
+
+    // Check if finished
+    if (!data.running) {
      stopUpdatePoll();
      if (data.result === "success") {
        onUpdateDone(true);
@@ -366,13 +348,12 @@ async function pollUpdateStatus() {
      }
    }
  } catch (err) {
-    // Server is likely restarting during nixos-rebuild switch
-    if (_serverDownSince === 0) {
-      _serverDownSince = Date.now();
-      appendLog("[Server restarting — waiting for it to come back…]");
+    // Server is likely restarting during nixos-rebuild switch — keep polling
+    if (!_serverWasDown) {
+      _serverWasDown = true;
+      appendLog("\n[Server restarting — waiting for it to come back…]\n\n");
      if ($modalStatus) $modalStatus.textContent = "Server restarting…";
    }
-    console.warn("Update poll failed (server may be restarting):", err);
  }
 }

@@ -415,7 +396,6 @@ if ($btnCloseModal)  $btnCloseModal.addEventListener("click", closeUpdateModal);
 if ($btnReboot)      $btnReboot.addEventListener("click", doReboot);
 if ($btnSave)        $btnSave.addEventListener("click", saveErrorReport);

-// Close modal on overlay click
 if ($modal) {
  $modal.addEventListener("click", (e) => {
    if (e.target === $modal) closeUpdateModal();
@@ -425,7 +405,6 @@ if ($modal) {
 // ── Init ──────────────────────────────────────────────────────────

 async function init() {
-  // Load config to get category labels
  try {
    const cfg = await apiFetch("/api/config");
    if (cfg.category_order) {
@@ -433,17 +412,14 @@ async function init() {
        _categoryLabels[key] = label;
      }
    }
-    // Update role badge
    const badge = document.getElementById("role-badge");
    if (badge && cfg.role_label) badge.textContent = cfg.role_label;
  } catch (_) {}

-  // Initial data loads
  await refreshServices();
  loadNetwork();
  checkUpdates();

-  // Polling
  setInterval(refreshServices, POLL_INTERVAL_SERVICES);
  setInterval(checkUpdates,    POLL_INTERVAL_UPDATES);
 }
--- a/modules/core/sovran-hub.nix
+++ b/modules/core/sovran-hub.nix
@@ -52,6 +52,61 @@ let
      services         = monitoredServices;
    });

+  # ── Update wrapper script ──────────────────────────────────────
+  update-script = pkgs.writeShellScript "sovran-hub-update.sh" ''
+    set -uo pipefail
+    export PATH="${lib.makeBinPath [ pkgs.nix pkgs.nixos-rebuild pkgs.git pkgs.flatpak pkgs.coreutils ]}:$PATH"
+
+    LOG="/var/log/sovran-hub-update.log"
+
+    # Truncate the log and redirect ALL output (stdout + stderr) into it
+    : > "$LOG"
+    exec > >(tee -a "$LOG") 2>&1
+
+    echo "══════════════════════════════════════════════════"
+    echo "  Sovran_SystemsOS Update — $(date)"
+    echo "══════════════════════════════════════════════════"
+    echo ""
+
+    RC=0
+
+    echo "── Step 1/3: nix flake update ────────────────────"
+    if ! nix flake update --flake /etc/nixos --print-build-logs 2>&1; then
+      echo "[ERROR] nix flake update failed"
+      RC=1
+    fi
+    echo ""
+
+    if [ "$RC" -eq 0 ]; then
+      echo "── Step 2/3: nixos-rebuild switch ──────────────────"
+      if ! nixos-rebuild switch --flake /etc/nixos --print-build-logs 2>&1; then
+        echo "[ERROR] nixos-rebuild switch failed"
+        RC=1
+      fi
+      echo ""
+    fi
+
+    if [ "$RC" -eq 0 ]; then
+      echo "── Step 3/3: flatpak update ────────────────────────"
+      if ! flatpak update -y 2>&1; then
+        echo "[WARNING] flatpak update failed (non-fatal)"
+      fi
+      echo ""
+    fi
+
+    if [ "$RC" -eq 0 ]; then
+      echo "══════════════════════════════════════════════════"
+      echo "  ✓ Update completed successfully"
+      echo "══════════════════════════════════════════════════"
+    else
+      echo "══════════════════════════════════════════════════"
+      echo "  ✗ Update failed — see errors above"
+      echo "══════════════════════════════════════════════════"
+    fi
+
+    exit "$RC"
+  '';
+
  sovran-hub-web = pkgs.python3Packages.buildPythonApplication {
    pname   = "sovran-systemsos-hub-web";
    version = "1.0.0";
@@ -133,13 +188,9 @@ in
    systemd.services.sovran-hub-update = {
      description = "Sovran_SystemsOS System Update";
      serviceConfig = {
-        Type           = "oneshot";
-        ExecStart      = "${pkgs.bash}/bin/bash -c 'cd /etc/nixos && nix flake update 2>&1 && nixos-rebuild switch 2>&1 && flatpak update -y 2>&1'";
-        StandardOutput = "journal";
-        StandardError  = "journal";
-        SyslogIdentifier = "sovran-hub-update";
+        Type       = "oneshot";
+        ExecStart  = "${update-script}";
      };
-      path = [ pkgs.nix pkgs.nixos-rebuild pkgs.git pkgs.flatpak ];
    };

    # ── Open firewall port ─────────────────────────────────────