Enhance logging and timing in CLI and session operations

- Updated the `_print_checks` function to replace console prints with logging functions for better traceability. - Introduced timing functionality in the `doctor`, `dry_run`, and `up` functions to log the duration of preflight checks. - Modified the `wait_ssh` function to accept a logging callback, improving SSH wait feedback. - Enhanced the `mark` method in `PhaseTimes` to log phase durations, aiding in performance analysis. - Updated various remote scripts to ensure error messages are printed to stderr for better error handling.
2026-08-21 08:03:04 +03:00
parent 7756d0d4df
commit ccba40a228
16 changed files with 205 additions and 46 deletions
@@ -61,20 +61,22 @@ def _print_checks(checks, *, quiet: bool = False) -> int:
    failed = blocking_failed(checks)
    if quiet:
        if failed:
-            console.print("[red]doctor: блокирующие проблемы[/red]")
+            err("doctor: блокирующие проблемы")
            for check in failed:
-                console.print(f"  • {check.name}: {check.detail}")
+                log(f"  • {check.name}: {check.detail}")
            _print_next_steps(failed)
            return 1
        warns = [c for c in checks if not c.ok and not c.blocking]
        if warns:
-            console.print(f"[yellow]doctor ok[/yellow] ({len(checks)}), предупреждения:")
+            warn(f"doctor ok ({len(checks)}), предупреждения:")
            for check in warns:
-                console.print(f"  • {check.name}: {check.detail}")
+                log(f"  • {check.name}: {check.detail}")
        else:
-            console.print(f"[green]doctor ok[/green] ({len(checks)} проверок)")
+            ok(f"doctor ok ({len(checks)} проверок)")
        return 0

+    from gpu_rent.timing import clock_prefix
+
    table = Table(title="gpu-rent doctor", show_lines=False)
    table.add_column("ok")
    table.add_column("проверка")
@@ -84,6 +86,7 @@ def _print_checks(checks, *, quiet: bool = False) -> int:
        mark = "[green]yes[/green]" if check.ok else "[red]NO[/red]"
        block = "да" if check.blocking else "нет"
        table.add_row(mark, check.name, block, check.detail)
+    console.print(f"[dim]{clock_prefix()}[/dim]таблица doctor ↓")
    console.print(table)
    if failed:
        console.print("\n[red]Сессию начинать нельзя.[/red] См. docs/setup.md")
@@ -130,8 +133,12 @@ def version() -> None:
 def doctor() -> None:
    """Preflight без create: Keystone, квота, flavor, диск, Civitai, манифесты."""
    try:
+        from gpu_rent.timing import clock_reset, format_duration, clock_elapsed
+
+        clock_reset()
        log("запускаю проверку…")
        checks = run_doctor()
+        log(f"проверка заняла {format_duration(clock_elapsed())}")
    except GpuRentError as exc:
        _die(exc)
    code = _print_checks(checks)
@@ -142,6 +149,9 @@ def doctor() -> None:
 def dry_run() -> None:
    """План без mutating-вызовов."""
    try:
+        from gpu_rent.timing import clock_reset
+
+        clock_reset()
        log("запускаю проверку…")
        checks = run_doctor()
        _print_checks(checks)
@@ -458,10 +468,13 @@ def up(
        )
        from gpu_rent.paths import vars_path
        from gpu_rent.prompts import MenuItem, prompt_menu
+        from gpu_rent.timing import clock_elapsed, clock_reset, format_duration
        from gpu_rent.varsfile import upsert_vars

+        clock_reset()
        log("запускаю проверку…")
        checks = run_doctor()
+        log(f"проверка заняла {format_duration(clock_elapsed())}")
        code = _print_checks(checks, quiet=not verbose)
        if code != 0:
            raise typer.Exit(1)
@@ -9,7 +9,7 @@ MARKER_DATA="${DATA_ROOT}/.gpu-rent-ready"
 MARKER_BOOT="${SWARM_ROOT}/.gpu-rent-bootstrapped"
 SWARM_REPO="https://github.com/mcmonkeyprojects/SwarmUI.git"

-log() { echo "[gpu-rent] $*"; }
+log() { echo "[gpu-rent] $*" >&2; }

 if [[ "$(id -u)" -ne 0 ]]; then
  echo "нужен root (sudo -n bash $0)" >&2
@@ -192,7 +192,7 @@ def main() -> int:
            print(f"{prefix} {reason}: {dest.name}")
        if auth_host == "civitai" and not token:
            failed += 1
-            print(f"{prefix} FAIL {dest.name}: нет CIVITAI токена", file=sys.stderr)
+            print(f"{prefix} FAIL {dest.name}: нет CIVITAI токена")
            continue
        try:
            print(f"{prefix} качаю: {dest.name}", flush=True)
@@ -218,7 +218,7 @@ def main() -> int:
            msg = str(exc)
            if "401" in msg and auth_host == "hf":
                msg += " — нужен HF_TOKEN в .env (huggingface.co/settings/tokens)"
-            print(f"{prefix} FAIL {dest.name}: {msg}", file=sys.stderr)
+            print(f"{prefix} FAIL {dest.name}: {msg}")
    TOKEN_PATH.unlink(missing_ok=True)
    HF_TOKEN_PATH.unlink(missing_ok=True)
    print(f"seed итог: скачано {downloaded}, пропущено {skipped}, ошибок {failed} (из {total})")
@@ -171,7 +171,7 @@ def update_installed_extras(known: set[str], update: bool, token: str = "") -> N
            try:
                update_tracking_branch(child, token=token)
            except Exception as exc:
-                print(f"FAIL installed {child}: {exc}", file=sys.stderr)
+                print(f"FAIL installed {child}: {exc}")
                raise


@@ -192,7 +192,7 @@ def main() -> int:
                clone_one(job, token, update)
            except Exception as exc:
                failed += 1
-                print(f"FAIL {job.get('dest')}: {exc}", file=sys.stderr)
+                print(f"FAIL {job.get('dest')}: {exc}")
        try:
            update_installed_extras(known, update, token=token)
        except Exception:
@@ -14,7 +14,7 @@ UNIT="gpu-rent-llamacpp"
 REPO="https://github.com/ggml-org/llama.cpp.git"
 API_BASE="https://api.github.com/repos/ggml-org/llama.cpp"

-log() { echo "[gpu-rent-llamacpp] $*"; }
+log() { echo "[gpu-rent-llamacpp] $*" >&2; }

 if [[ "$(id -u)" -ne 0 ]]; then
  echo "нужен root" >&2
@@ -66,11 +66,11 @@ print(cands[0][1] if cands else "")
 }

 resolve_release_tag() {
+  # stdout = tag only (no log lines — callers capture via $())
  if [[ -n "$LLAMACPP_TAG" ]]; then
    echo "$LLAMACPP_TAG"
    return
  fi
-  log "WARN: LLAMACPP_TAG/ASSET_URL не заданы — берём latest (нет pin). См. docs/llm.md"
  curl -fsSL "${API_BASE}/releases/latest" | python3 -c \
    'import json,sys; print(json.load(sys.stdin).get("tag_name") or "")'
 }
@@ -228,9 +228,13 @@ else
    echo "asset-url" >"$STAMP"
    chown "${SWARM_USER}:${SWARM_USER}" "$STAMP"
  else
+    if [[ -z "$LLAMACPP_TAG" ]]; then
+      log "WARN: LLAMACPP_TAG/ASSET_URL не заданы — берём latest (нет pin). См. docs/llm.md"
+    fi
    tag="$(resolve_release_tag)"
-    if [[ -z "$tag" ]]; then
-      log "не удалось определить release tag"
+    tag="$(printf '%s' "$tag" | tr -d '\r' | head -n1 | awk 'NF{print; exit}')"
+    if [[ -z "$tag" || "$tag" == *" "* || "$tag" == *"["* ]]; then
+      log "не удалось определить release tag (got: ${tag:-empty})"
      exit 1
    fi
    if ! build_cuda_from_source "$tag"; then
@@ -10,7 +10,7 @@ UNIT="gpu-rent-ollama"
 GPU_JSON="${DATA_ROOT}/.gpu-rent-gpu.json"
 OLLAMA_ENV_FILE="${DATA_ROOT}/.gpu-rent-ollama.env"

-log() { echo "[gpu-rent-ollama] $*"; }
+log() { echo "[gpu-rent-ollama] $*" >&2; }

 if [[ "$(id -u)" -ne 0 ]]; then
  echo "нужен root" >&2
@@ -123,7 +123,7 @@ def main() -> int:
            except OSError:
                pass
    if not JOBS.is_file():
-        print("no jobs file", file=sys.stderr)
+        print("no jobs file")
        return 1
    jobs = json.loads(JOBS.read_text(encoding="utf-8"))
    if not isinstance(jobs, list) or not jobs:
@@ -167,7 +167,7 @@ def main() -> int:
                        " — токен есть, но отказано: проверь scopes / "
                        "Accept license на странице модели"
                    )
-            print(f"FAIL {name}: {msg}", file=sys.stderr)
+            print(f"FAIL {name}: {msg}")
            try:
                dest.with_suffix(dest.suffix + ".partial").unlink(missing_ok=True)
            except OSError:
@@ -110,7 +110,7 @@ def pull_stream(name: str, label: str) -> None:

 def main() -> int:
    if not JOBS.is_file():
-        print("no jobs file", file=sys.stderr)
+        print("no jobs file")
        return 1
    models = json.loads(JOBS.read_text(encoding="utf-8"))
    if not isinstance(models, list) or not models:
@@ -135,7 +135,7 @@ def main() -> int:
                have.add(name)
            except (urllib.error.URLError, urllib.error.HTTPError, OSError, TimeoutError, RuntimeError) as exc:
                failed += 1
-                print(f"FAIL pull {name}: {exc}", file=sys.stderr)
+                print(f"FAIL pull {name}: {exc}")
    finally:
        MARKER.unlink(missing_ok=True)
    if failed:
@@ -53,7 +53,7 @@ def main() -> int:
    try:
        raw = json.loads(KEYS_PATH.read_text(encoding="utf-8"))
    except (OSError, json.JSONDecodeError) as exc:
-        print(f"bad keys file: {exc}", file=sys.stderr)
+        print(f"bad keys file: {exc}")
        return 1
    finally:
        try:
@@ -74,13 +74,13 @@ def main() -> int:
                {"session_id": sid, "keyType": key_type, "key": value},
            )
        except (urllib.error.URLError, urllib.error.HTTPError, TimeoutError, OSError, json.JSONDecodeError) as exc:
-            print(f"SetAPIKey {key_type} failed: {exc}", file=sys.stderr)
+            print(f"SetAPIKey {key_type} failed: {exc}")
            return 1
        if resp.get("error"):
-            print(f"SetAPIKey {key_type}: {resp['error']}", file=sys.stderr)
+            print(f"SetAPIKey {key_type}: {resp['error']}")
            return 1
        if not resp.get("success"):
-            print(f"SetAPIKey {key_type}: unexpected {resp}", file=sys.stderr)
+            print(f"SetAPIKey {key_type}: unexpected {resp}")
            return 1
        print(f"SetAPIKey {key_type}=ok")
    return 0
@@ -88,8 +88,8 @@ def _bind_access(
    if fip_id:
        state.floating_ip_id = fip_id
    save_state(state)
-    wait_ssh(cfg, ip)
-    clock.mark("SSH")
+    wait_ssh(cfg, ip, log=log)
+    clock.mark("SSH", log)
    log(f"SSH {cfg.ssh_user}@{ip}")
    state.phase = "bootstrapping"
    save_state(state)
@@ -141,7 +141,7 @@ def _bind_access(
            log("bootstrap: FULL llm-only — маркера data ready нет")

    run_bootstrap(cfg, ip, log, update=update and swarm, light=light)
-    clock.mark("bootstrap")
+    clock.mark("bootstrap", log)
    provision_vm(
        cfg,
        ip,
@@ -150,13 +150,13 @@ def _bind_access(
        server_id=getattr(server, "id", None) or state.server_id,
        update=update,
    )
-    clock.mark("provision")
+    clock.mark("provision", log)
    if swarm:
        try:
            wait_backend_idle(cfg, ip, log)
        except CloudError as exc:
            log(f"ready: {exc}")
-        clock.mark("Idle")
+        clock.mark("Idle", log)
        try:
            if tune_swarm_perf(cfg, ip, log):
                log("systemctl restart swarmui (perf ExtraArgs)")
@@ -169,12 +169,12 @@ def _bind_access(
                log("perf tune: restart не нужен")
        except Exception as exc:
            log(f"perf tune: {exc}")
-        clock.mark("perf")
+        clock.mark("perf", log)
        try:
            seed_swarmui_api_keys(cfg, ip, log)
        except Exception as exc:
            log(f"SwarmUI API keys: {exc}")
-        clock.mark("api-keys")
+        clock.mark("api-keys", log)
    else:
        log("ready: llm-only (без ожидания SwarmUI Idle)")

@@ -190,7 +190,7 @@ def _bind_access(
        state.notes["stack_vm_error"] = str(exc)[:500]
        save_state(state)
        raise
-    clock.mark("verify")
+    clock.mark("verify", log)

    try:
        gpu_checks = verify_gpu_env(cfg, ip, log, timeout=600.0)
@@ -204,7 +204,7 @@ def _bind_access(
        state.notes["gpu_env_error"] = str(exc)[:500]
        save_state(state)
        raise
-    clock.mark("gpu-env")
+    clock.mark("gpu-env", log)

    try:
        ensure_boot_snapshot(
@@ -243,7 +243,8 @@ def _bind_access(
    state.notes["enable_swarmui"] = swarm
    state.notes["up_timing"] = clock.summary_line()
    save_state(state)
-    log(f"тайминг up: {clock.summary_line()}")
+    for line in clock.summary_lines():
+        log(line)
    return state


@@ -171,7 +171,12 @@ def probe_ssh(cfg: Config, host: str, attempts: int = 3) -> str:
    return "auth" if auth_seen else "down"


-def wait_ssh(cfg: Config, host: str, timeout: float = 900.0) -> None:
+def wait_ssh(
+    cfg: Config,
+    host: str,
+    timeout: float = 900.0,
+    log: Callable[[str], None] | None = None,
+) -> None:
    """Wait until sshd accepts our key. Paramiko banner noise is muted.

    AuthenticationException is normal while cloud-init injects keys: keep
@@ -183,6 +188,8 @@ def wait_ssh(cfg: Config, host: str, timeout: float = 900.0) -> None:
    logging.getLogger("paramiko").setLevel(logging.CRITICAL)
    logging.getLogger("paramiko.transport").setLevel(logging.CRITICAL)

+    emit = log if log is not None else print
+
    # sshd may answer before authorized_keys is ready (boot-from-volume / user_data).
    auth_give_up = 180.0

@@ -223,7 +230,7 @@ def wait_ssh(cfg: Config, host: str, timeout: float = 900.0) -> None:
            except Exception:
                pass
            if attempt == 1 or attempt % 6 == 0:
-                print(f"жду SSH {cfg.ssh_user}@{host}… ({name})", flush=True)
+                emit(f"жду SSH {cfg.ssh_user}@{host}… ({name})")
            if (
                is_auth
                and auth_streak_started is not None
@@ -323,6 +330,10 @@ def run_script_sudo(
        _stream_pty_output(stdout, log=log, chunks=chunks)
        code = stdout.channel.recv_exit_status()
        err = stderr.read().decode("utf-8", errors="replace") if not stdout.channel.closed else ""
+        # PTY usually merges stderr; if anything remains, don't drop it past timed log.
+        if log and err.strip():
+            for line in err.strip().splitlines():
+                log(line)
        out = "".join(chunks)
        if code != 0:
            raise CloudError(f"remote script exit {code}: {err or out[-2000:]}")
@@ -354,6 +365,9 @@ def run_python(
        _stream_pty_output(stdout, log=log, chunks=chunks)
        code = stdout.channel.recv_exit_status()
        err = stderr.read().decode("utf-8", errors="replace") if not stdout.channel.closed else ""
+        if log and err.strip():
+            for line in err.strip().splitlines():
+                log(line)
        out = "".join(chunks)
        if code != 0:
            raise CloudError(f"remote python exit {code}: {err or out[-2000:]}")
@@ -96,7 +96,11 @@ def _end_progress_line() -> None:
 def _emit_progress(msg: str) -> None:
    """Overwrite the current terminal line (download bars)."""
    global _progress_active, _progress_width
+    from gpu_rent.timing import clock_prefix
+
    text = msg.replace("\r", "").replace("\n", "")
+    # Keep elapsed visible on the progress line itself.
+    text = clock_prefix() + text
    pad = max(0, _progress_width - len(text))
    sys.stdout.write("\r" + text + (" " * pad))
    sys.stdout.flush()
@@ -105,38 +109,54 @@ def _emit_progress(msg: str) -> None:


 def log(msg: str = "") -> None:
-    """CLI log callback — colored print.
+    """CLI log callback — colored print with elapsed ``[+12s]`` prefix.

    Messages starting with ``\\r`` update one progress line in place
    (used by SSH stream for download bars).
    """
+    from gpu_rent.timing import clock_prefix
+
    if msg.startswith("\r"):
        _emit_progress(msg[1:])
        return
    _end_progress_line()
-    console.print(paint(msg))
+    if msg == "":
+        console.print()
+        return
+    prefix = clock_prefix()
+    console.print(f"[dim]{escape(prefix)}[/dim]{paint(msg)}")


 def ok(msg: str) -> None:
+    from gpu_rent.timing import clock_prefix
+
    _end_progress_line()
-    console.print(f"[green]{escape(msg)}[/green]")
+    console.print(f"[dim]{escape(clock_prefix())}[/dim][green]{escape(msg)}[/green]")


 def warn(msg: str) -> None:
+    from gpu_rent.timing import clock_prefix
+
    _end_progress_line()
-    console.print(f"[yellow]{escape(msg)}[/yellow]")
+    console.print(f"[dim]{escape(clock_prefix())}[/dim][yellow]{escape(msg)}[/yellow]")


 def err(msg: str) -> None:
+    from gpu_rent.timing import clock_prefix
+
    _end_progress_line()
-    console.print(f"[red]{escape(msg)}[/red]")
+    console.print(f"[dim]{escape(clock_prefix())}[/dim][red]{escape(msg)}[/red]")


 def info(msg: str) -> None:
+    from gpu_rent.timing import clock_prefix
+
    _end_progress_line()
-    console.print(f"[cyan]{escape(msg)}[/cyan]")
+    console.print(f"[dim]{escape(clock_prefix())}[/dim][cyan]{escape(msg)}[/cyan]")


 def dim(msg: str) -> None:
+    from gpu_rent.timing import clock_prefix
+
    _end_progress_line()
-    console.print(f"[dim]{escape(msg)}[/dim]")
+    console.print(f"[dim]{escape(clock_prefix() + msg)}[/dim]")
@@ -5,6 +5,22 @@ from __future__ import annotations
 import time
 from collections.abc import Callable

+# kind: wait = heartbeat/reassure; work = optimize candidate; quick = fine
+PHASE_META: dict[str, tuple[str, str]] = {
+    "cloud": ("work", "create/unshelve/volumes в API"),
+    "SSH": ("wait", "ожидание boot/SSH — нужен heartbeat"),
+    "bootstrap": ("work", "FULL apt/dotnet; LIGHT если маркер есть"),
+    "provision": ("work", "seed/extensions/LLM — смотри прогресс"),
+    "Idle": ("wait", "ждём SwarmUI Idle"),
+    "perf": ("quick", ""),
+    "api-keys": ("quick", ""),
+    "verify": ("wait", "poll HTTP на VM"),
+    "gpu-env": ("wait", "poll nvidia/CUDA/torch"),
+    "doctor": ("wait", "Keystone/квоты/Glance — нужен старт-лог"),
+}
+
+_clock_t0: float | None = None
+

 def format_duration(seconds: float) -> str:
    sec = max(0, int(round(seconds)))
@@ -17,6 +33,29 @@ def format_duration(seconds: float) -> str:
    return f"{hours}h {rem_m}m" if rem_m else f"{hours}h"


+def clock_reset() -> None:
+    """Start a new elapsed clock (call at the beginning of up/doctor)."""
+    global _clock_t0
+    _clock_t0 = time.monotonic()
+
+
+def clock_ensure() -> None:
+    global _clock_t0
+    if _clock_t0 is None:
+        _clock_t0 = time.monotonic()
+
+
+def clock_elapsed() -> float:
+    clock_ensure()
+    assert _clock_t0 is not None
+    return time.monotonic() - _clock_t0
+
+
+def clock_prefix() -> str:
+    """``[+12s] `` / ``[+1m 5s] `` for log lines."""
+    return f"[+{format_duration(clock_elapsed())}] "
+
+
 class PhaseTimes:
    """Record named milestones from a shared start."""

@@ -24,9 +63,13 @@ class PhaseTimes:
        self._t0 = time.monotonic()
        self._marks: list[tuple[str, float]] = []

-    def mark(self, name: str) -> float:
+    def mark(self, name: str, log: Callable[[str], None] | None = None) -> float:
        elapsed = time.monotonic() - self._t0
+        prev = self._marks[-1][1] if self._marks else 0.0
+        delta = elapsed - prev
        self._marks.append((name, elapsed))
+        if log is not None:
+            log(f"фаза {name}: {format_duration(delta)} · всего {format_duration(elapsed)}")
        return elapsed

    @property
@@ -47,6 +90,23 @@ class PhaseTimes:
        parts.append(f"всего {format_duration(self.total)}")
        return " · ".join(parts)

+    def summary_lines(self) -> list[str]:
+        """Multi-line report with wait/optimize hints."""
+        lines = ["тайминг up:"]
+        for name, dt in self.deltas():
+            kind, note = PHASE_META.get(name, ("", ""))
+            tag = ""
+            if kind == "wait" and dt >= 20:
+                tag = " [ожидание]"
+            elif kind == "work" and dt >= 60:
+                tag = " [оптимизировать?]"
+            extra = ""
+            if note and (dt >= 30 or (kind == "work" and dt >= 15)):
+                extra = f" — {note}"
+            lines.append(f"  {name}: {format_duration(dt)}{tag}{extra}")
+        lines.append(f"  всего: {format_duration(self.total)}")
+        return lines
+

 class WaitLog:
    """Log first wait message, then at most every `every` seconds."""
@@ -144,7 +144,7 @@ def _recover_unshelve(cfg: Config, log: Log) -> str:
    state.phase = "ready_tunneled"
    save_state(state)
    log(f"жду SSH на {ip}…")
-    wait_ssh(cfg, ip, timeout=420)
+    wait_ssh(cfg, ip, timeout=420, log=log)
    return ip


@@ -35,7 +35,7 @@ def _mock_bind(monkeypatch):
        "gpu_rent.session.ensure_floating_ip",
        lambda conn, server, existing_id, existing_addr, log: ("203.0.113.9", "fip1"),
    )
-    monkeypatch.setattr("gpu_rent.session.wait_ssh", lambda cfg, host, timeout=900.0: None)
+    monkeypatch.setattr("gpu_rent.session.wait_ssh", lambda cfg, host, timeout=900.0, log=None: None)
    monkeypatch.setattr(
        "gpu_rent.session.run_ssh",
        lambda cfg, host, command, **kw: (
@@ -1,4 +1,11 @@
-from gpu_rent.timing import PhaseTimes, WaitLog, format_duration
+from gpu_rent.timing import (
+    PhaseTimes,
+    WaitLog,
+    clock_elapsed,
+    clock_prefix,
+    clock_reset,
+    format_duration,
+)


 def test_format_duration():
@@ -20,6 +27,36 @@ def test_phase_times_summary(monkeypatch):
    assert "всего" in line


+def test_phase_times_mark_logs(monkeypatch):
+    times = iter([0.0, 45.0])
+    monkeypatch.setattr("gpu_rent.timing.time.monotonic", lambda: next(times))
+    logs: list[str] = []
+    clock = PhaseTimes()
+    clock.mark("SSH", logs.append)
+    assert logs == ["фаза SSH: 45s · всего 45s"]
+
+
+def test_phase_summary_lines_annotate_long_work(monkeypatch):
+    # t0=0, mark provision at 120s
+    times = iter([0.0, 120.0, 120.0])
+    monkeypatch.setattr("gpu_rent.timing.time.monotonic", lambda: next(times))
+    clock = PhaseTimes()
+    clock.mark("provision")
+    lines = clock.summary_lines()
+    assert lines[0] == "тайминг up:"
+    assert any("provision" in ln and "оптимизировать?" in ln for ln in lines)
+    assert any("seed/extensions/LLM" in ln for ln in lines)
+
+
+def test_phase_summary_lines_annotate_wait(monkeypatch):
+    times = iter([0.0, 40.0, 40.0])
+    monkeypatch.setattr("gpu_rent.timing.time.monotonic", lambda: next(times))
+    clock = PhaseTimes()
+    clock.mark("SSH")
+    lines = clock.summary_lines()
+    assert any("SSH" in ln and "ожидание" in ln for ln in lines)
+
+
 def test_wait_log_throttles(monkeypatch):
    logs: list[str] = []
    t = {"now": 0.0}
@@ -31,3 +68,13 @@ def test_wait_log_throttles(monkeypatch):
    t["now"] = 31.0
    w.tick("c")
    assert logs == ["a", "c"]
+
+
+def test_clock_prefix(monkeypatch):
+    t = {"now": 100.0}
+    monkeypatch.setattr("gpu_rent.timing.time.monotonic", lambda: t["now"])
+    clock_reset()
+    assert clock_prefix() == "[+0s] "
+    t["now"] = 112.0
+    assert clock_prefix() == "[+12s] "
+    assert clock_elapsed() == 12.0