From f4251109cd93d26394f91ae9570b140adf2007de Mon Sep 17 00:00:00 2001 From: xiami762 <> Date: Fri, 24 Apr 2026 13:13:44 +0800 Subject: [PATCH] fix(cli): improve daemon logs, serve timestamps, and upgrade journal Add uvicorn log_config with wall-clock timestamps for backend.log when daemonized. Set PYTHONUNBUFFERED for the backend child and print recent log lines on probe failure. Persist upgrade outcomes to update.log from the updater and the flocks update CLI, with tests. Made-with: Cursor --- flocks/cli/commands/update.py | 5 +++ flocks/cli/main.py | 18 ++++++++++- flocks/cli/service_manager.py | 26 ++++++++++++++++ flocks/updater/updater.py | 43 +++++++++++++++++++++----- flocks/utils/log.py | 19 ++++++++++++ tests/cli/test_service_manager.py | 21 +++++++++---- tests/cli/test_uvicorn_log_config.py | 11 +++++++ tests/utils/test_append_upgrade_log.py | 18 +++++++++++ 8 files changed, 146 insertions(+), 15 deletions(-) create mode 100644 tests/cli/test_uvicorn_log_config.py create mode 100644 tests/utils/test_append_upgrade_log.py diff --git a/flocks/cli/commands/update.py b/flocks/cli/commands/update.py index 84649c8eb..464483048 100644 --- a/flocks/cli/commands/update.py +++ b/flocks/cli/commands/update.py @@ -9,6 +9,8 @@ from rich.panel import Panel from rich.table import Table +from flocks.utils.log import append_upgrade_text_log + console = Console() @@ -39,6 +41,7 @@ async def _update(check: bool, yes: bool, force: bool = False, region: str | Non info = await check_update(region=region) if info.error: + append_upgrade_text_log(f"ERROR version_check: {info.error}") console.print(f"[red]检查失败：{info.error}[/red]") raise typer.Exit(1) @@ -76,6 +79,7 @@ async def _update(check: bool, yes: bool, force: bool = False, region: str | Non prompt = "\n当前已是最新版本，是否仍强制重新安装？" confirmed = typer.confirm(prompt, default=False) if not confirmed: + append_upgrade_text_log("INFO update_cancelled user_declined") console.print("[yellow]已取消[/yellow]") return @@ -131,6 +135,7 @@ def _finish_active(success: bool = True) -> None: console.print(f"[cyan][{step}/{total_steps}] {label}...[/cyan] ", end="") active_stage = progress.stage + append_upgrade_text_log(f"OK cli_update_completed version={version_to_apply}") console.print(f"\n[green]✓ 升级完成 → v{version_to_apply}[/green]") console.print("[dim]如有后台服务正在运行，请执行 [bold]flocks restart[/bold] 重启服务[/dim]") diff --git a/flocks/cli/main.py b/flocks/cli/main.py index d9be59ff4..a19bf1f65 100644 --- a/flocks/cli/main.py +++ b/flocks/cli/main.py @@ -8,7 +8,7 @@ import os import sys from pathlib import Path -from typing import Optional +from typing import Any, Optional import typer from dotenv import load_dotenv @@ -289,6 +289,21 @@ def logs( _handle_service_error(error) +def _uvicorn_log_config() -> dict[str, Any]: + """Uvicorn logging with wall-clock timestamps (visible in ``backend.log`` when daemonized).""" + import copy + + from uvicorn.config import LOGGING_CONFIG + + cfg = copy.deepcopy(LOGGING_CONFIG) + stamp_fmt = "%Y-%m-%d %H:%M:%S" + for name in ("default", "access"): + formatter = cfg["formatters"][name] + formatter["fmt"] = "%(asctime)s | " + formatter["fmt"] + formatter["datefmt"] = stamp_fmt + return cfg + + @app.command(hidden=True) def serve( host: str = typer.Option("127.0.0.1", "--host", "-h", help="Server host"), @@ -311,6 +326,7 @@ def serve( port=port, reload=reload, log_level="info", + log_config=_uvicorn_log_config(), ) diff --git a/flocks/cli/service_manager.py b/flocks/cli/service_manager.py index 4bc6493bb..819723f18 100644 --- a/flocks/cli/service_manager.py +++ b/flocks/cli/service_manager.py @@ -749,6 +749,7 @@ def start_backend(config: ServiceConfig, console) -> None: backend_env = os.environ.copy() backend_env["_FLOCKS_WEBUI_HOST"] = config.frontend_host backend_env["_FLOCKS_WEBUI_PORT"] = str(config.frontend_port) + backend_env["PYTHONUNBUFFERED"] = "1" console.print("[flocks] 启动后端服务...") process = _spawn_process( @@ -772,9 +773,11 @@ def start_backend(config: ServiceConfig, console) -> None: wait_for_http( [backend_access_base_url(config)], "后端服务", + delay=3.0, validator=_is_running_status_response, ) except ServiceError: + _emit_service_log_tail(console, paths.backend_log, "后端") stop_one(config.backend_port, paths.backend_pid, "后端", console) raise @@ -882,6 +885,7 @@ def start_frontend(config: ServiceConfig, console) -> None: try: wait_for_http([config.frontend_url], "WebUI") except ServiceError: + _emit_service_log_tail(console, paths.frontend_log, "WebUI") stop_one(config.frontend_port, paths.frontend_pid, "WebUI", console) raise @@ -1277,6 +1281,28 @@ def tail_lines(path: Path, lines: int) -> list[str]: return [line.rstrip("\n") for line in deque(handle, maxlen=max(lines, 0))] +def _emit_service_log_tail(console, log_path: Path, service_label: str, lines: int = 40) -> None: + """Print the last *lines* lines of *log_path* to help diagnose failed daemon startups.""" + if lines <= 0: + return + if not log_path.exists(): + console.print( + f"[dim][flocks] {service_label} 日志文件尚不存在（{log_path}），" + "子进程可能启动即退出。[/dim]", + ) + return + try: + excerpt = tail_lines(log_path, lines) + except OSError as exc: + console.print(f"[dim][flocks] 无法读取 {service_label} 日志: {exc}[/dim]") + return + if not excerpt: + return + console.print(f"[yellow][flocks] {service_label} 近期日志（最后 {len(excerpt)} 行）:[/yellow]") + for line in excerpt: + console.print(f"[dim]{line}[/dim]") + + def append_unique_pids(existing: Iterable[int], additions: Iterable[int]) -> list[int]: """Return a deduplicated pid list preserving order.""" result: list[int] = [] diff --git a/flocks/updater/updater.py b/flocks/updater/updater.py index eb05e5aba..42bfe205f 100644 --- a/flocks/updater/updater.py +++ b/flocks/updater/updater.py @@ -62,6 +62,13 @@ log = Log.create(service="updater") +def _record_update_journal(message: str) -> None: + """Append a human-readable line to ``update.log`` (see ``append_upgrade_text_log``).""" + from flocks.utils.log import append_upgrade_text_log + + append_upgrade_text_log(message) + + @dataclass(frozen=True) class UpdateMirrorProfile: """Resolved download/runtime mirror settings for a single upgrade request.""" @@ -1826,9 +1833,11 @@ async def perform_update( except Exception as exc: shutil.rmtree(tmp_dir, ignore_errors=True) log.error("updater.download.all_failed", {"error": str(exc)}) + _dl_msg = "Failed to download the update. Please check your network connection." + _record_update_journal(f"ERROR {_dl_msg} ({exc})") yield UpdateProgress( stage="error", - message="Failed to download the update. Please check your network connection.", + message=_dl_msg, success=False, ) return @@ -1868,6 +1877,7 @@ async def perform_update( msg = f"Failed to extract files: {exc}" if backup_path: msg += f"\nRestore from backup: {backup_path}" + _record_update_journal(f"ERROR {msg}") yield UpdateProgress(stage="error", message=msg, success=False) return @@ -1888,9 +1898,11 @@ async def perform_update( ) if code != 0: shutil.rmtree(tmp_dir, ignore_errors=True) + _fe_dep = f"Frontend dependency install failed: {err}" + _record_update_journal(f"ERROR {_fe_dep}") yield UpdateProgress( stage="error", - message=f"Frontend dependency install failed: {err}", + message=_fe_dep, success=False, ) return @@ -1904,9 +1916,11 @@ async def perform_update( ) if code != 0: shutil.rmtree(tmp_dir, ignore_errors=True) + _fe_build = f"Frontend build failed: {err}" + _record_update_journal(f"ERROR {_fe_build}") yield UpdateProgress( stage="error", - message=f"Frontend build failed: {err}", + message=_fe_build, success=False, ) return @@ -1920,9 +1934,11 @@ async def perform_update( dist_index = staged_webui_dir / "dist" / "index.html" if not dist_index.exists(): shutil.rmtree(tmp_dir, ignore_errors=True) + _fe_miss = "Frontend build output is missing; upgrade aborted before cutover." + _record_update_journal(f"ERROR {_fe_miss}") yield UpdateProgress( stage="error", - message="Frontend build output is missing; upgrade aborted before cutover.", + message=_fe_miss, success=False, ) return @@ -1958,6 +1974,7 @@ async def perform_update( msg = f"Failed to replace files: {exc}" if backup_path: msg += f"\nRestore from backup: {backup_path}" + _record_update_journal(f"ERROR {msg}") yield UpdateProgress(stage="error", message=msg, success=False) return @@ -1983,6 +2000,7 @@ async def perform_update( ) if sys.platform == "win32": hint = "Dependency sync failed: uv is required to refresh the Windows project runtime." + _record_update_journal(f"ERROR {hint}") yield UpdateProgress(stage="error", message=hint, success=False) return @@ -2011,7 +2029,9 @@ async def perform_update( install_root, current_version, ) - yield UpdateProgress(stage="error", message=f"Dependency sync failed: {err}", success=False) + _sync_err = f"Dependency sync failed: {err}" + _record_update_journal(f"ERROR {_sync_err}") + yield UpdateProgress(stage="error", message=_sync_err, success=False) return if sys.platform == "win32": @@ -2025,6 +2045,7 @@ async def perform_update( install_root, current_version, ) + _record_update_journal(f"ERROR {validation_error}") yield UpdateProgress(stage="error", message=validation_error, success=False) return @@ -2075,9 +2096,11 @@ async def perform_update( restart_argv = _build_restart_argv(install_root) except Exception as exc: log.error("updater.restart.build_argv_failed", {"error": str(exc)}) + _rb_msg = f"Failed to build restart command: {exc}" + _record_update_journal(f"ERROR {_rb_msg}") yield UpdateProgress( stage="error", - message=f"Failed to build restart command: {exc}", + message=_rb_msg, success=False, ) return @@ -2104,9 +2127,11 @@ async def perform_update( rollback_upgrade_handover() except Exception: pass + _rs_win = f"Failed to restart service: {exc}" + _record_update_journal(f"ERROR {_rs_win}") yield UpdateProgress( stage="error", - message=f"Failed to restart service: {exc}", + message=_rs_win, success=False, ) return @@ -2121,9 +2146,11 @@ async def perform_update( rollback_upgrade_handover() except Exception: pass + _rs_unix = f"Failed to restart service: {exc}" + _record_update_journal(f"ERROR {_rs_unix}") yield UpdateProgress( stage="error", - message=f"Failed to restart service: {exc}", + message=_rs_unix, success=False, ) return diff --git a/flocks/utils/log.py b/flocks/utils/log.py index 786c61dcd..7d3c46ec0 100644 --- a/flocks/utils/log.py +++ b/flocks/utils/log.py @@ -33,6 +33,25 @@ def get_log_dir() -> Path: return _log_dir() +def append_upgrade_text_log(message: str) -> None: + """Append timestamped lines to ``update.log`` under the configured log directory. + + Used for upgrade flows so errors remain on disk when the process had no TTY + or when structured ``Log`` output went to a different file than ``backend.log``. + """ + try: + log_dir = _log_dir() + log_dir.mkdir(parents=True, exist_ok=True) + path = log_dir / "update.log" + stamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S") + normalized = message.replace("\r\n", "\n").replace("\r", "\n") + with path.open("a", encoding="utf-8") as handle: + for segment in normalized.split("\n"): + handle.write(f"{stamp} | {segment}\n") + except OSError: + return + + # Log levels - matches TypeScript exactly class LogLevel: """Log levels""" diff --git a/tests/cli/test_service_manager.py b/tests/cli/test_service_manager.py index ff7c1984c..7c2c79e55 100644 --- a/tests/cli/test_service_manager.py +++ b/tests/cli/test_service_manager.py @@ -767,11 +767,14 @@ def test_start_backend_writes_runtime_metadata(monkeypatch, tmp_path: Path) -> N "resolve_flocks_cli_command", lambda root=None: ["python", "-m", "flocks.cli.main"], ) - monkeypatch.setattr( - service_manager, - "_spawn_process", - lambda *_args, **_kwargs: SimpleNamespace(pid=2468), - ) + spawn_env: dict[str, str] | None = None + + def _capture_spawn(*_args, **kwargs) -> SimpleNamespace: + nonlocal spawn_env + spawn_env = kwargs.get("env") + return SimpleNamespace(pid=2468) + + monkeypatch.setattr(service_manager, "_spawn_process", _capture_spawn) service_manager.start_backend(service_manager.ServiceConfig(), console) @@ -795,9 +798,11 @@ def test_start_backend_writes_runtime_metadata(monkeypatch, tmp_path: Path) -> N "urls": ["http://127.0.0.1:8000"], "name": "后端服务", "attempts": 30, - "delay": 1.0, + "delay": 3.0, "validator": service_manager._is_running_status_response, }] + assert spawn_env is not None + assert spawn_env.get("PYTHONUNBUFFERED") == "1" def test_start_backend_rolls_back_when_probe_fails(monkeypatch, tmp_path: Path) -> None: @@ -812,6 +817,7 @@ def test_start_backend_rolls_back_when_probe_fails(monkeypatch, tmp_path: Path) ) paths.run_dir.mkdir(parents=True) paths.log_dir.mkdir(parents=True) + paths.backend_log.write_text("line1\nline2\nboot failed here\n", encoding="utf-8") console = DummyConsole() stop_calls: list[tuple[int, Path, str]] = [] @@ -845,6 +851,9 @@ def test_start_backend_rolls_back_when_probe_fails(monkeypatch, tmp_path: Path) service_manager.start_backend(service_manager.ServiceConfig(), console) assert stop_calls == [(8000, paths.backend_pid, "后端")] + joined = "\n".join(console.messages) + assert "近期日志" in joined + assert "boot failed here" in joined def test_start_backend_reports_started_after_probe_succeeds(monkeypatch, tmp_path: Path) -> None: diff --git a/tests/cli/test_uvicorn_log_config.py b/tests/cli/test_uvicorn_log_config.py new file mode 100644 index 000000000..9b91b2ab7 --- /dev/null +++ b/tests/cli/test_uvicorn_log_config.py @@ -0,0 +1,11 @@ +"""Uvicorn log config used by ``flocks serve``.""" + +from flocks.cli import main as cli_main + + +def test_uvicorn_log_config_adds_asctime_to_formatters() -> None: + cfg = cli_main._uvicorn_log_config() + assert "%(asctime)s |" in cfg["formatters"]["default"]["fmt"] + assert "%(asctime)s |" in cfg["formatters"]["access"]["fmt"] + assert cfg["formatters"]["default"]["datefmt"] == "%Y-%m-%d %H:%M:%S" + assert cfg["formatters"]["access"]["datefmt"] == "%Y-%m-%d %H:%M:%S" diff --git a/tests/utils/test_append_upgrade_log.py b/tests/utils/test_append_upgrade_log.py new file mode 100644 index 000000000..666253689 --- /dev/null +++ b/tests/utils/test_append_upgrade_log.py @@ -0,0 +1,18 @@ +"""Tests for ``append_upgrade_text_log``.""" + +import re +from pathlib import Path + +from flocks.utils.log import append_upgrade_text_log + + +def test_append_upgrade_text_log_writes_timestamped_lines(monkeypatch, tmp_path: Path) -> None: + monkeypatch.setenv("FLOCKS_LOG_DIR", str(tmp_path)) + append_upgrade_text_log("first line") + append_upgrade_text_log("a\nb") + text = (tmp_path / "update.log").read_text(encoding="utf-8") + lines = text.strip().splitlines() + assert len(lines) == 3 + assert re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \| first line$", lines[0]) + assert re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \| a$", lines[1]) + assert re.match(r"^\d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2} \| b$", lines[2])