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 9fdb9cf0d..bdd1c3918 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 @@ -291,6 +291,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"), @@ -313,6 +328,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 62116444f..5d7871250 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 c2416b3d1..00744c775 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.""" @@ -1903,9 +1910,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 @@ -1945,6 +1954,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 @@ -1965,9 +1975,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 @@ -1981,9 +1993,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 @@ -1997,9 +2011,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 @@ -2092,6 +2108,7 @@ async def _restore_after_apply_failure() -> None: ) 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 @@ -2203,7 +2220,7 @@ async def _restore_after_apply_failure() -> None: handover_active = False yield UpdateProgress( stage="error", - message=f"Failed to build restart command: {exc}", + message=_rb_msg, success=False, ) return @@ -2234,7 +2251,7 @@ async def _restore_after_apply_failure() -> None: handover_active = False yield UpdateProgress( stage="error", - message=f"Failed to restart service: {exc}", + message=_rs_win, success=False, ) return @@ -2252,7 +2269,7 @@ async def _restore_after_apply_failure() -> None: handover_active = False 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 3935dbdc9..05144067b 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])