updated logging

app/sovran_systemsos_web/server.py

@@ -7,6 +7,7 @@ import json
 import os
 import socket
 import subprocess
+import time
 import urllib.request
 
 from fastapi import FastAPI, HTTPException
@@ -69,6 +70,12 @@ if os.path.isdir(_ICONS_DIR):
 
 templates = Jinja2Templates(directory=os.path.join(_BASE_DIR, "templates"))
 
+# ── Track when we started an update ──────────────────────────────
+# This timestamp lets us know that an update was recently kicked off,
+# so we don't prematurely declare it finished if the unit hasn't
+# transitioned to "active" yet.
+_update_started_at: float = 0.0
+
 # ── Update check helpers ─────────────────────────────────────────
 
 def _get_locked_info():
@@ -166,6 +173,15 @@ def _update_is_active() -> bool:
     return r.returncode == 0
 
 
+def _update_state() -> str:
+    """Return the ActiveState of the update unit."""
+    r = subprocess.run(
+        ["systemctl", "show", "-p", "ActiveState", "--value", UPDATE_UNIT],
+        capture_output=True, text=True,
+    )
+    return r.stdout.strip()
+
+
 def _update_result() -> str:
     """Return 'success', 'failed', or 'unknown'."""
     r = subprocess.run(
@@ -326,6 +342,7 @@ async def api_reboot():
 @app.post("/api/updates/run")
 async def api_updates_run():
     """Kick off the detached update systemd unit."""
+    global _update_started_at
     loop = asyncio.get_event_loop()
 
     running = await loop.run_in_executor(None, _update_is_active)
@@ -339,6 +356,9 @@ async def api_updates_run():
         stderr=asyncio.subprocess.DEVNULL,
     )
 
+    # Record the start time so we can handle the race condition
+    _update_started_at = time.monotonic()
+
     proc = await asyncio.create_subprocess_exec(
         "systemctl", "start", "--no-block", UPDATE_UNIT,
         stdout=asyncio.subprocess.DEVNULL,
@@ -352,14 +372,33 @@ async def api_updates_run():
 @app.get("/api/updates/status")
 async def api_updates_status(offset: int = 0):
     """Poll endpoint: returns running state, result, and new log content."""
+    global _update_started_at
     loop = asyncio.get_event_loop()
 
-    running = await loop.run_in_executor(None, _update_is_active)
+    active = await loop.run_in_executor(None, _update_is_active)
+    state = await loop.run_in_executor(None, _update_state)
     result = await loop.run_in_executor(None, _update_result)
     new_log, new_offset = await loop.run_in_executor(None, _read_log, offset)
 
+    # Race condition guard: if we just started the unit and it hasn't
+    # transitioned to "activating"/"active" yet, report it as still running.
+    # Give it up to 10 seconds to appear as active.
+    if not active and _update_started_at > 0:
+        elapsed = time.monotonic() - _update_started_at
+        if elapsed < 10 and state in ("inactive", ""):
+            # Unit hasn't started yet — tell the frontend it's still running
+            return {
+                "running": True,
+                "result": "pending",
+                "log": new_log,
+                "offset": new_offset,
+            }
+        else:
+            # Either it finished or the grace period expired
+            _update_started_at = 0.0
+
     return {
-        "running": running,
+        "running": active,
         "result": result,
         "log": new_log,
         "offset": new_offset,

app/sovran_systemsos_web/static/app.js

@@ -5,6 +5,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   = 1500;   // 1.5 s while update is running
+const UPDATE_POLL_DELAY      = 3000;   // 3 s before first poll (let unit start)
 
 const CATEGORY_ORDER = [
   "infrastructure",
@@ -28,6 +29,7 @@ let _updatePollTimer = null;
 let _updateLogOffset = 0;
 let _serverWasDown   = false;
 let _updateFinished  = false;
+let _sawRunning      = false;
 
 // ── DOM refs ──────────────────────────────────────────────────────
 
@@ -255,7 +257,6 @@ async function checkUpdates() {
     if ($updateBadge) {
       $updateBadge.classList.toggle("visible", hasUpdates);
     }
-    // Toggle button color: blue (default) → green (updates available)
     if ($updateBtn) {
       $updateBtn.classList.toggle("has-updates", hasUpdates);
     }
@@ -270,6 +271,7 @@ function openUpdateModal() {
   _updateLogOffset = 0;
   _serverWasDown = false;
   _updateFinished = false;
+  _sawRunning = false;
   if ($modalLog)      $modalLog.textContent = "";
   if ($modalStatus)   $modalStatus.textContent = "Starting update…";
   if ($modalSpinner)  $modalSpinner.classList.add("spinning");
@@ -307,9 +309,11 @@ function startUpdate() {
     .then(data => {
       if (data.status === "already_running") {
         appendLog("[Update already in progress, attaching…]\n\n");
+        _sawRunning = true;
       }
       if ($modalStatus) $modalStatus.textContent = "Updating…";
-      startUpdatePoll();
+      // Delay the first poll to give the systemd unit time to start
+      setTimeout(startUpdatePoll, UPDATE_POLL_DELAY);
     })
     .catch(err => {
       appendLog(`[Error: failed to start update — ${err}]\n`);
@@ -330,7 +334,6 @@ function stopUpdatePoll() {
 }
 
 async function pollUpdateStatus() {
-  // Don't poll if we already know it's done
   if (_updateFinished) return;
 
   try {
@@ -348,8 +351,14 @@ async function pollUpdateStatus() {
     }
     _updateLogOffset = data.offset;
 
-    // Check if finished
+    // Track if we ever saw the unit as running
-    if (!data.running) {
+    if (data.running) {
+      _sawRunning = true;
+    }
+
+    // Only declare finished if we previously saw it running (or server says so)
+    // This prevents the race where the unit hasn't started yet
+    if (!data.running && _sawRunning) {
       _updateFinished = true;
       stopUpdatePoll();
       if (data.result === "success") {
@@ -359,7 +368,9 @@ async function pollUpdateStatus() {
       }
     }
   } catch (err) {
-    // Server is likely restarting during nixos-rebuild switch — keep polling
+    // Server is likely restarting during nixos-rebuild switch
+    // This counts as "saw running" since it was running before it died
+    _sawRunning = true;
     if (!_serverWasDown) {
       _serverWasDown = true;
       appendLog("\n[Server restarting — waiting for it to come back…]\n\n");
@@ -413,7 +424,7 @@ if ($modal) {
   });
 }
 
-// ── Init ──────<EFBFBD><EFBFBD>───────────────────────────────────────────────────
+// ── Init ──────────────────────────────────────────────────────────
 
 async function init() {
   try {