Add detailed runtime container logging

Dockerfile

@@ -31,4 +31,4 @@ USER user
 
 EXPOSE 7860
 
-CMD ["gunicorn", "--bind", "0.0.0.0:7860", "--workers", "1", "--threads", "8", "--timeout", "180", "app:app"]
+CMD ["gunicorn", "--bind", "0.0.0.0:7860", "--workers", "1", "--threads", "8", "--timeout", "180", "--log-level", "info", "--error-logfile", "-", "--capture-output", "app:app"]

core/runtime_logging.py

@@ -0,0 +1,34 @@
+from __future__ import annotations
+
+import logging
+import os
+import sys
+
+
+DEFAULT_LOG_LEVEL = os.getenv("APP_LOG_LEVEL", "INFO").upper()
+LOG_FORMAT = "%(asctime)s | %(levelname)s | %(name)s | %(message)s"
+
+
+def configure_logging(level: str | None = None) -> None:
+    resolved_level_name = (level or DEFAULT_LOG_LEVEL).upper()
+    resolved_level = getattr(logging, resolved_level_name, logging.INFO)
+    formatter = logging.Formatter(LOG_FORMAT)
+
+    root_logger = logging.getLogger()
+    if not root_logger.handlers:
+        handler = logging.StreamHandler(sys.stdout)
+        handler.setFormatter(formatter)
+        root_logger.addHandler(handler)
+    else:
+        for handler in root_logger.handlers:
+            handler.setFormatter(formatter)
+
+    root_logger.setLevel(resolved_level)
+    logging.captureWarnings(True)
+
+    for logger_name in ("gunicorn.error", "gunicorn.access", "werkzeug"):
+        logging.getLogger(logger_name).setLevel(resolved_level)
+
+
+def get_logger(name: str) -> logging.Logger:
+    return logging.getLogger(name)

core/task_manager.py

@@ -1,5 +1,6 @@
 from __future__ import annotations
 
+import logging
 import threading
 import time
 from dataclasses import dataclass
@@ -9,6 +10,9 @@ from core.db import Database
 from core.security import SecretBox
 
 
+LOGGER = logging.getLogger("sacc.task_manager")
+
+
 @dataclass(slots=True)
 class RunningTask:
     task_id: int
@@ -27,35 +31,60 @@ class TaskManager:
         self._shutdown_event = threading.Event()
         self._dispatcher_thread: threading.Thread | None = None
         self._running: dict[int, RunningTask] = {}
+        self._last_dispatch_snapshot: tuple[int, int, int] | None = None
 
     def start(self) -> None:
         with self._startup_lock:
             if self._started:
+                LOGGER.info("Task manager start skipped because it is already running")
                 return
+            LOGGER.info(
+                "Task manager starting | db_path=%s default_parallel_limit=%s",
+                self.store.path,
+                getattr(self.config, "default_parallel_limit", "-"),
+            )
             self.store.reset_inflight_tasks()
             self._dispatcher_thread = threading.Thread(target=self._dispatch_loop, name="task-dispatcher", daemon=True)
             self._dispatcher_thread.start()
             self._started = True
+            LOGGER.info("Task manager started")
 
     def shutdown(self) -> None:
+        LOGGER.info("Task manager shutdown requested")
         self._shutdown_event.set()
         with self._running_lock:
             for running_task in self._running.values():
                 running_task.stop_event.set()
+        LOGGER.info("Task manager stop signal broadcast to %s running task(s)", self._running_count())
 
     def queue_task(self, user_id: int, requested_by: str, requested_by_role: str) -> tuple[dict, bool]:
         active_task = self.store.find_active_task_for_user(user_id)
         if active_task is not None:
+            LOGGER.info(
+                "Task queue skipped because an active task already exists | task_id=%s user_id=%s status=%s",
+                active_task["id"],
+                user_id,
+                active_task["status"],
+            )
             return self.store.get_task(active_task["id"]) or active_task, False
 
         task_id = self.store.create_task(user_id, requested_by, requested_by_role)
+        LOGGER.info(
+            "Task queued | task_id=%s user_id=%s requested_by_role=%s requested_by=%s",
+            task_id,
+            user_id,
+            requested_by_role,
+            requested_by,
+        )
         self._log(task_id, user_id, "SYSTEM", "INFO", f"任务已进入队列，触发者: {requested_by_role}:{requested_by}")
         return self.store.get_task(task_id), True
 
     def stop_task(self, task_id: int) -> bool:
         requested = self.store.request_task_stop(task_id)
         if not requested:
+            LOGGER.info("Task stop request ignored because task is not active | task_id=%s", task_id)
             return False
+        LOGGER.info("Task stop requested | task_id=%s", task_id)
         self._log(task_id, None, "SYSTEM", "INFO", "收到停止请求，任务会在安全节点退出。")
         with self._running_lock:
             running_task = self._running.get(task_id)
@@ -64,44 +93,70 @@ class TaskManager:
         return True
 
     def _dispatch_loop(self) -> None:
+        LOGGER.info("Dispatcher loop started")
         while not self._shutdown_event.is_set():
             self._cleanup_running_registry()
             parallel_limit = self.store.get_parallel_limit()
             running_count = self._running_count()
             available_slots = max(0, parallel_limit - running_count)
+            pending_tasks: list[dict] = []
             if available_slots > 0:
                 pending_tasks = self.store.list_pending_tasks(available_slots)
+
+            snapshot = (parallel_limit, running_count, len(pending_tasks))
+            if snapshot != self._last_dispatch_snapshot and (running_count > 0 or pending_tasks):
+                LOGGER.info(
+                    "Dispatcher snapshot | parallel_limit=%s running=%s available_slots=%s fetched_pending=%s",
+                    parallel_limit,
+                    running_count,
+                    available_slots,
+                    len(pending_tasks),
+                )
+                self._last_dispatch_snapshot = snapshot
+
+            if pending_tasks:
                 for task in pending_tasks:
                     if self._shutdown_event.is_set():
                         break
                     if not task["is_active"]:
+                        LOGGER.warning(
+                            "Queued task cancelled because user is inactive | task_id=%s user_id=%s",
+                            task["id"],
+                            task["user_id"],
+                        )
                         self.store.finish_task(task["id"], "failed", "该用户已被禁用，任务未执行。")
                         self._log(task["id"], task["user_id"], "SYSTEM", "WARNING", "用户已禁用，队���中的任务被取消。")
                         continue
                     self._launch_task(task["id"])
             time.sleep(1)
+        LOGGER.info("Dispatcher loop stopped")
 
     def _launch_task(self, task_id: int) -> None:
         with self._running_lock:
             if task_id in self._running:
+                LOGGER.info("Task launch skipped because thread already exists | task_id=%s", task_id)
                 return
             stop_event = threading.Event()
             thread = threading.Thread(target=self._run_task, args=(task_id, stop_event), name=f"task-{task_id}", daemon=True)
             self._running[task_id] = RunningTask(task_id=task_id, thread=thread, stop_event=stop_event)
+            LOGGER.info("Launching task thread | task_id=%s thread_name=%s", task_id, thread.name)
             thread.start()
 
     def _run_task(self, task_id: int, stop_event: threading.Event) -> None:
         task = self.store.get_task(task_id)
         if task is None:
+            LOGGER.warning("Task record disappeared before execution | task_id=%s", task_id)
             self._remove_running(task_id)
             return
 
         user = self.store.get_user(task["user_id"])
         if user is None:
+            LOGGER.error("Task cannot start because user does not exist | task_id=%s user_id=%s", task_id, task["user_id"])
             self.store.finish_task(task_id, "failed", "用户不存在。")
             self._remove_running(task_id)
             return
 
+        LOGGER.info("Task runner starting | task_id=%s user_id=%s", task_id, user["id"])
         self.store.mark_task_running(task_id)
         self._log(task_id, user["id"], "SYSTEM", "INFO", "任务开始执行。")
 
@@ -117,6 +172,7 @@ class TaskManager:
             )
             result = bot.run(stop_event)
         except Exception as exc:  # pragma: no cover - defensive fallback
+            LOGGER.exception("Task initialization failed | task_id=%s user_id=%s", task_id, user["id"])
             result = TaskResult(status="failed", error=str(exc))
             self._log(task_id, user["id"], "SYSTEM", "ERROR", f"任务初始化失败: {exc}")
 
@@ -131,10 +187,28 @@ class TaskManager:
         final_text = result.error or f"任务已结束，状态: {final_status}"
         level = "ERROR" if final_status == "failed" else "INFO"
         self._log(task_id, user["id"], "SYSTEM", level, final_text)
+        LOGGER.info(
+            "Task runner finished | task_id=%s user_id=%s final_status=%s",
+            task_id,
+            user["id"],
+            final_status,
+        )
         self._remove_running(task_id)
 
     def _log(self, task_id: int | None, user_id: int | None, scope: str, level: str, message: str) -> None:
         self.store.add_log(task_id, user_id, scope, level, message)
+        self._emit_runtime_log(task_id=task_id, user_id=user_id, scope=scope, level=level, message=message)
+
+    @staticmethod
+    def _emit_runtime_log(*, task_id: int | None, user_id: int | None, scope: str, level: str, message: str) -> None:
+        upper_level = level.upper()
+        rendered = f"task_id={task_id or '-'} user_id={user_id or '-'} scope={scope} level={upper_level} | {message}"
+        if upper_level == "ERROR":
+            LOGGER.error(rendered)
+        elif upper_level == "WARNING":
+            LOGGER.warning(rendered)
+        else:
+            LOGGER.info(rendered)
 
     def _running_count(self) -> int:
         with self._running_lock:
@@ -148,7 +222,11 @@ class TaskManager:
                     finished_ids.append(task_id)
             for task_id in finished_ids:
                 self._running.pop(task_id, None)
+        for task_id in finished_ids:
+            LOGGER.info("Task thread cleaned from registry | task_id=%s", task_id)
 
     def _remove_running(self, task_id: int) -> None:
         with self._running_lock:
-            self._running.pop(task_id, None)
+            removed = self._running.pop(task_id, None)
+        if removed is not None:
+            LOGGER.info("Task removed from running registry | task_id=%s", task_id)

space_app.py

@@ -1,4 +1,4 @@
-from __future__ import annotations
+from __future__ import annotations
 
 import atexit
 import json
@@ -6,14 +6,18 @@ import time
 from functools import wraps
 from typing import Callable
 
-from flask import Flask, Response, flash, jsonify, redirect, render_template, request, session, stream_with_context, url_for
+from flask import Flask, Response, flash, g, jsonify, redirect, render_template, request, session, stream_with_context, url_for
 
 from core.config import AppConfig
 from core.db import Database
 from core.security import SecretBox, hash_password, verify_password
 from core.task_manager import TaskManager
+from core.runtime_logging import configure_logging, get_logger
 
 
+configure_logging()
+APP_LOGGER = get_logger("sacc.web")
+
 config = AppConfig.load()
 store = Database(config.db_path, default_parallel_limit=config.default_parallel_limit)
 store.init_db()
@@ -55,6 +59,14 @@ atexit.register(task_manager.shutdown)
 app = Flask(__name__, template_folder="templates", static_folder="static")
 app.secret_key = config.session_secret
 app.config.update(SESSION_COOKIE_HTTPONLY=True, SESSION_COOKIE_SAMESITE="Lax")
+APP_LOGGER.info(
+    "Application bootstrap complete | data_dir=%s db_path=%s chrome_binary=%s chromedriver_path=%s default_parallel_limit=%s",
+    config.data_dir,
+    config.db_path,
+    config.chrome_binary,
+    config.chromedriver_path,
+    config.default_parallel_limit,
+)
 
 CATEGORY_LABELS = {
     "plan": "方案选课",
@@ -70,6 +82,51 @@ TASK_LABELS = {
 }
 
 
+SKIPPED_REQUEST_LOG_PREFIXES = (
+    "/static/",
+    "/api/",
+)
+SKIPPED_REQUEST_LOG_PATHS = {
+    "/favicon.ico",
+}
+
+
+def _current_actor_label() -> str:
+    role = session.get("role", "guest")
+    if role == "user":
+        return f"user:{session.get('user_id', '-')}"
+    if role == "admin":
+        return f"admin:{session.get('admin_username', '-')}"
+    return "guest"
+
+
+@app.before_request
+def before_request_logging() -> None:
+    g.request_started_at = time.perf_counter()
+
+
+@app.after_request
+def after_request_logging(response):
+    if request.path in SKIPPED_REQUEST_LOG_PATHS:
+        return response
+    if any(request.path.startswith(prefix) for prefix in SKIPPED_REQUEST_LOG_PREFIXES):
+        return response
+
+    started_at = getattr(g, "request_started_at", None)
+    duration_ms = 0.0 if started_at is None else (time.perf_counter() - started_at) * 1000
+    remote_addr = request.headers.get("x-forwarded-for") or request.remote_addr or "-"
+    APP_LOGGER.info(
+        "HTTP %s %s -> %s in %.1fms | actor=%s remote=%s",
+        request.method,
+        request.path,
+        response.status_code,
+        duration_ms,
+        _current_actor_label(),
+        remote_addr,
+    )
+    return response
+
+
 @app.context_processor
 def inject_globals() -> dict:
     return {
@@ -517,4 +574,4 @@ def stream_admin_logs():
     response = Response(generate(), mimetype="text/event-stream")
     response.headers["Cache-Control"] = "no-cache"
     response.headers["X-Accel-Buffering"] = "no"
-    return response
+    return response