From 43797eedeb5d017c800d78b62fcd8e3e2ac09578 Mon Sep 17 00:00:00 2001 From: Linghong Date: Fri, 17 Jul 2026 13:40:33 +0000 Subject: [PATCH] Split logging: prose event stream vs structured JSONL access stream Rule: bulk per-request data never lands in the prose log; everything with analysis value goes to a structured file. - Event stream (stderr, text): startup summary, warnings, tracebacks -- what supervisord/journald already captures. Human-readable, low volume. - Access stream: one JSONL record per request (plus a "startup" meta record with the instance config) written to BGFILTER_ACCESS_LOG, app-rotated 50MB x 5; falls back to stderr when unset (dev). Failed requests carry a truncated `exc` copy so the access file is self-contained; the full traceback stays in the event stream, joined by request_id. - BGFILTER_LOG_FORMAT retired: format is now a property of the stream, not a global switch. - uvicorn runs with --no-access-log everywhere (deploy script + unit examples): its prose per-request lines duplicated a subset of ours. - deploy_autodl.sh --log-dir now provisions both files; docs updated (EN+ZH: env table, AutoDL section, run/systemd examples). Co-Authored-By: Claude Opus 4.8 --- DEPLOY.md | 20 ++++++---- DEPLOY_ZH.md | 19 ++++++---- app.py | 80 ++++++++++++++++++++++++++++++++-------- scripts/deploy_autodl.sh | 14 ++++--- 4 files changed, 98 insertions(+), 35 deletions(-) diff --git a/DEPLOY.md b/DEPLOY.md index cb6a882..6c9f1dd 100644 --- a/DEPLOY.md +++ b/DEPLOY.md @@ -40,7 +40,7 @@ Arguments: | `--open` | — | Explicitly remove the token and run OPEN (no auth). | | `--port ` | `6006` | In-container listen port (matches the AutoDL public port mapping). | | `--config ` | `configs/gpu.yaml` | Pipeline config. | -| `--log-dir ` | `~/autodl-tmp` | Directory for the service log `bgfilter.log`. Defaults to the AutoDL persistent data disk `~/autodl-tmp` (survives container resets, unlike `/tmp`). | +| `--log-dir ` | `~/autodl-tmp` | Log directory (AutoDL persistent data disk by default — survives container resets, unlike `/tmp`). Holds `bgfilter.log` (prose event log) and `bgfilter-access.jsonl` (structured per-request log, app-rotated). | **Assumes**: repo already checked out (no `git pull`), root user, torch/CUDA provided by the AutoDL image, python at `/root/miniconda3`. @@ -64,8 +64,9 @@ $S stop bgfilter # stop the service (supervisord keeps running) $S start bgfilter # start it again $S shutdown # stop everything, incl. supervisord itself -tail -f ~/autodl-tmp/bgfilter.log # service log (dir set by --log-dir) -tail -f ~/supervisord.log # supervisord's own log (when the service won't start) +tail -f ~/autodl-tmp/bgfilter.log # event log: startup/warnings/tracebacks (prose) +tail -f ~/autodl-tmp/bgfilter-access.jsonl # access log: one JSON record per request +tail -f ~/supervisord.log # supervisord's own log (service won't start?) ``` If supervisord itself is not running — fresh container restart with no shell @@ -283,8 +284,8 @@ redirect back to `huggingface.co`, which recent `huggingface_hub` rejects with | `BGFILTER_FETCH_MAX_BYTES` | `26214400` | `image_url` mode: cap the downloaded body (~25 MB) → `413`. No SSRF filtering — keep auth on / callers trusted. | | `BGFILTER_FETCH_TIMEOUT` | `15` | `image_url` mode: read timeout (s) for the fetch (connect fixed at 5 s). Outbound fetch concurrency is fixed at `2 × cpu_workers` (hard cap 64). | | `BGFILTER_PRELOAD` | `1` | Load default models at startup (first request isn't cold) | -| `BGFILTER_LOG_FORMAT` | `text` | `text` (human) or `json` (one structured object per line, for log shippers). Each request emits one access line with a `request_id`, params, and stage timings (`t_queue/fetch/decode/process/total_ms`); the id is also echoed as the `X-Request-ID` response header. | -| `BGFILTER_LOG_LEVEL` | `INFO` | Root log level. | +| `BGFILTER_ACCESS_LOG` | — | Path of the **structured access log** (JSONL, one record per request + one `startup` meta record; app-rotated at 50 MB × 5). Fields: `request_id`, params, sizes, stage timings (`t_queue/fetch/decode/process/total_ms`), status, truncated `exc` on failures; the id is also echoed as the `X-Request-ID` response header. Unset = records fall back to stderr (dev). The prose **event log** (startup/warnings/tracebacks) always goes to stderr for supervisord/journald to capture — per-request data never lands there. | +| `BGFILTER_LOG_LEVEL` | `INFO` | Root log level (event stream). | | `BGFILTER_CROSS_CHECK` | config (`on`) | Force the cross-check veto on/off (`0` disables; needs `BiRefNet_HR-matting`) | | `BGFILTER_CPU_WORKERS` | config `server.cpu_workers` (`1`) | Thread-pool size for request pipelining. `1` = strictly serial (one request at a time). `>1` lets that many requests run concurrently, overlapping their CPU stages while a GPU mutex serializes the model forwards — keeps the GPU fed instead of idle. Biggest win when the pipeline is CPU-bound (e.g. cross-check off). Set it in the config (`server:` section) or override per box with this env var. | | `BGFILTER_GPU_CONCURRENCY` | config `server.gpu_concurrency` (`1`) | How many requests may be inside a GPU forward at once. `1` = single-stream (safe). `2` lets two forwards co-schedule on the SMs (batch-1 underfills them), raising GPU-bound throughput — but concurrent activations multiply VRAM, so size it as `weights + N × peak_forward ≤ VRAM` (on a 32 GB card, `2` peaks ~19 GB at 2048 cross-check; keep `1` on ≤16 GB). Needs `cpu_workers>1` to matter. Config key `server.gpu_concurrency`; this env var overrides it. | @@ -329,7 +330,8 @@ Two model knobs live in the **config file** (`model:` section), not env vars: ## 7. Run the service ```bash -python -m uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 +BGFILTER_ACCESS_LOG=logs/bgfilter-access.jsonl \ +python -m uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 --no-access-log ``` - **Keep `--workers 1`.** Each worker loads its own full copy of the models; more @@ -337,6 +339,9 @@ python -m uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 inference with a global lock. - `--host 127.0.0.1` exposes it to the local host only (intended for a co-located caller). See §10 for remote access. +- `--no-access-log` silences uvicorn's prose per-request lines — they duplicate (a + subset of) the app's structured access records (§6, `BGFILTER_ACCESS_LOG`), and + per-request data does not belong in the prose stream. ## 8. Run as a systemd service @@ -359,9 +364,10 @@ Environment=BGFILTER_CONFIG=configs/default.yaml Environment=BGFILTER_DEVICE=cpu Environment=BGFILTER_MAX_IMAGE_PIXELS=4194304 Environment=BGFILTER_PRELOAD=1 +Environment=BGFILTER_ACCESS_LOG=/opt/genarrative-image-host/bgfilter-service/logs/bgfilter-access.jsonl Environment=OMP_NUM_THREADS=4 Environment=MKL_NUM_THREADS=4 -ExecStart=/opt/genarrative-image-host/bgfilter-service/.venv/bin/uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 +ExecStart=/opt/genarrative-image-host/bgfilter-service/.venv/bin/uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 --no-access-log Restart=on-failure RestartSec=5 MemoryMax=8G diff --git a/DEPLOY_ZH.md b/DEPLOY_ZH.md index 922ca01..8d8131f 100644 --- a/DEPLOY_ZH.md +++ b/DEPLOY_ZH.md @@ -34,7 +34,7 @@ scripts/deploy_autodl.sh --token | `--open` | — | 显式删除 token、以开放模式运行（无鉴权）。 | | `--port ` | `6006` | 容器内监听端口（对应 AutoDL 的公网映射端口）。 | | `--config ` | `configs/gpu.yaml` | 流水线配置。 | -| `--log-dir ` | `~/autodl-tmp` | 服务日志 `bgfilter.log` 所在目录。默认落在 AutoDL 持久数据盘 `~/autodl-tmp`（容器重置不丢），而非 `/tmp`。 | +| `--log-dir ` | `~/autodl-tmp` | 日志目录（默认 AutoDL 持久数据盘——容器重置不丢，`/tmp` 会丢）。含 `bgfilter.log`（散文事件日志）和 `bgfilter-access.jsonl`（结构化每请求日志，应用自轮转）。 | **前提**：仓库已 checkout（脚本不 `git pull`）、root 用户、torch/CUDA 由 AutoDL 镜像提供、 python 在 `/root/miniconda3`。 @@ -56,8 +56,9 @@ $S stop bgfilter # 停服务（supervisord 本身继续跑） $S start bgfilter # 再启动 $S shutdown # 全部停掉，包括 supervisord 自己 -tail -f ~/autodl-tmp/bgfilter.log # 服务日志（目录由 --log-dir 决定） -tail -f ~/supervisord.log # supervisord 自己的日志（服务起不来时看这个） +tail -f ~/autodl-tmp/bgfilter.log # 事件日志:启动/告警/堆栈（散文） +tail -f ~/autodl-tmp/bgfilter-access.jsonl # 访问日志:每请求一条 JSON 记录 +tail -f ~/supervisord.log # supervisord 自己的日志（服务起不来时看） ``` 若 supervisord 本身没在跑——容器刚重启还没开过 shell，或报 socket 残留错误——照 @@ -257,8 +258,8 @@ export HF_HUB_DISABLE_XET=1 # 这些 repo 是 Xet 存储；强 | `BGFILTER_CONFIG` | `configs/default.yaml` | 管线配置文件 | | `BGFILTER_DEVICE` | `cpu` | 同时覆盖 model 和 segmentation 的 device（GPU 用 `cuda`）| | `BGFILTER_MAX_IMAGE_PIXELS` | `4194304` | 超过则返回 `413`（约 4 MP）| -| `BGFILTER_LOG_FORMAT` | `text` | `text`（人读）或 `json`（每行一条结构化对象,便于日志采集）。每请求打一行访问日志,含 `request_id`、参数、分阶段耗时（`t_queue/fetch/decode/process/total_ms`）;该 id 同时以 `X-Request-ID` 响应头返回。 | -| `BGFILTER_LOG_LEVEL` | `INFO` | 根日志级别。 | +| `BGFILTER_ACCESS_LOG` | — | **结构化访问日志**的路径（JSONL,每请求一条记录 + 一条 `startup` 元记录;应用自轮转,50 MB × 5）。字段:`request_id`、参数、尺寸、分阶段耗时（`t_queue/fetch/decode/process/total_ms`）、状态码、失败时截断的 `exc`;该 id 同时以 `X-Request-ID` 响应头返回。不设置 = 记录回退到 stderr（开发用）。散文**事件日志**（启动/告警/堆栈）始终走 stderr 由 supervisord/journald 捕获——每请求数据绝不落在散文流里。 | +| `BGFILTER_LOG_LEVEL` | `INFO` | 根日志级别（事件流）。 | | `BGFILTER_FETCH_MAX_BYTES` | `26214400` | `image_url` 模式：下载体上限（约 25 MB）→ `413`。无 SSRF 过滤——务必开鉴权 / 调用方可信。 | | `BGFILTER_FETCH_TIMEOUT` | `15` | `image_url` 模式：fetch 读超时（秒；连接超时固定 5 秒）。出站 fetch 并发固定为 `2 × cpu_workers`（硬顶 64）。 | | `BGFILTER_PRELOAD` | `1` | 启动时预加载默认模型（首个请求不用冷加载）| @@ -299,12 +300,15 @@ export HF_HUB_DISABLE_XET=1 # 这些 repo 是 Xet 存储；强 ## 7. 运行服务 ```bash -python -m uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 +BGFILTER_ACCESS_LOG=logs/bgfilter-access.jsonl \ +python -m uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 --no-access-log ``` - **必须保留 `--workers 1`。** 每个 worker 各加载一整套模型，多 worker 会成倍占内存 （8 GB 机器会 OOM）。服务已用全局锁串行化推理。 - `--host 127.0.0.1` 只对本机开放（面向同机调用方）。跨机访问见 §10。 +- `--no-access-log` 关掉 uvicorn 自己的散文版每请求日志——它是应用结构化访问记录 + （§6 `BGFILTER_ACCESS_LOG`）的子集、纯重复，且每请求数据不该进散文流。 ## 8. 作为 systemd 服务运行 @@ -327,9 +331,10 @@ Environment=BGFILTER_CONFIG=configs/default.yaml Environment=BGFILTER_DEVICE=cpu Environment=BGFILTER_MAX_IMAGE_PIXELS=4194304 Environment=BGFILTER_PRELOAD=1 +Environment=BGFILTER_ACCESS_LOG=/opt/genarrative-image-host/bgfilter-service/logs/bgfilter-access.jsonl Environment=OMP_NUM_THREADS=4 Environment=MKL_NUM_THREADS=4 -ExecStart=/opt/genarrative-image-host/bgfilter-service/.venv/bin/uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 +ExecStart=/opt/genarrative-image-host/bgfilter-service/.venv/bin/uvicorn app:app --host 127.0.0.1 --port 18083 --workers 1 --no-access-log Restart=on-failure RestartSec=5 MemoryMax=8G diff --git a/app.py b/app.py index a94a4c2..4491690 100644 --- a/app.py +++ b/app.py @@ -16,9 +16,11 @@ import logging import os import re import time +import traceback import uuid from concurrent.futures import ThreadPoolExecutor from contextlib import asynccontextmanager +from logging.handlers import RotatingFileHandler from pathlib import Path from urllib.parse import urlparse @@ -33,7 +35,6 @@ from bgfilter.service import SEG_MODELS, PipelineManager # Per-request correlation id. A middleware sets it; a logging filter injects it into # every record so all logs for one request share the id. contextvars (not thread- # locals) so a pooled worker thread never inherits the previous request's id. -LOG_FORMAT = os.environ.get("BGFILTER_LOG_FORMAT", "json").strip().lower() _request_id_var: contextvars.ContextVar[str] = contextvars.ContextVar("request_id", default="-") _RID_RE = re.compile(r"^[A-Za-z0-9._-]{1,64}$") @@ -72,24 +73,45 @@ class _JsonFormatter(logging.Formatter): return json.dumps(out, ensure_ascii=False) -_log_handler = logging.StreamHandler() -_log_handler.addFilter(_RequestIdFilter()) -_log_handler.setFormatter( - _JsonFormatter() - if LOG_FORMAT == "json" - else logging.Formatter("%(asctime)s %(levelname)s %(name)s [%(request_id)s] %(message)s") +# Two log streams with distinct jobs (never mixed into one file): +# +# * Event stream -- prose for humans, low volume: startup summary, warnings, error +# tracebacks. Goes to stderr (text format) where supervisord/journald captures it. +# Per-request records must NOT be logged here: bulk structured content does not +# belong in the prose file. +# * Access stream -- structured JSONL, one record per request (plus one "startup" +# meta record): everything with analysis value. Written to the file named by +# BGFILTER_ACCESS_LOG (rotated by the app itself: supervisord can't rotate a file +# it doesn't own); when unset (dev), the JSON lines fall back to stderr. +# +# Both streams stamp the same request_id, so a traceback in the event stream joins +# back to its access record (which also carries a truncated `exc` copy). +_event_handler = logging.StreamHandler() +_event_handler.addFilter(_RequestIdFilter()) +_event_handler.setFormatter( + logging.Formatter("%(asctime)s %(levelname)s %(name)s [%(request_id)s] %(message)s") ) -logging.basicConfig(level=os.environ.get("BGFILTER_LOG_LEVEL", "INFO"), handlers=[_log_handler]) +logging.basicConfig(level=os.environ.get("BGFILTER_LOG_LEVEL", "INFO"), handlers=[_event_handler]) logger = logging.getLogger("bgfilter.app") + +ACCESS_LOG_PATH = os.environ.get("BGFILTER_ACCESS_LOG", "").strip() access_logger = logging.getLogger("bgfilter.access") +access_logger.propagate = False # never leak per-request records into the prose stream +if ACCESS_LOG_PATH: + Path(ACCESS_LOG_PATH).parent.mkdir(parents=True, exist_ok=True) + _access_handler: logging.Handler = RotatingFileHandler( + ACCESS_LOG_PATH, maxBytes=50 * 1024 * 1024, backupCount=5, encoding="utf-8" + ) +else: + _access_handler = logging.StreamHandler() +_access_handler.addFilter(_RequestIdFilter()) +_access_handler.setFormatter(_JsonFormatter()) +access_logger.addHandler(_access_handler) -def _emit_access(fields: dict) -> None: - """One access line per request. JSON mode merges the fields; text mode joins them.""" - if LOG_FORMAT == "json": - access_logger.info("request", extra={"fields": fields}) - else: - access_logger.info(" ".join(f"{k}={v}" for k, v in fields.items() if k != "request_id")) +def _emit_access(event: str, fields: dict) -> None: + """One JSONL record on the access stream (`msg` = record type).""" + access_logger.info(event, extra={"fields": fields}) VERSION = "0.1.0" _HEX_RE = re.compile(r"^#[0-9a-fA-F]{6}$") @@ -200,6 +222,7 @@ async def lifespan(app: FastAPI): timeout=httpx.Timeout(connect=5.0, read=FETCH_TIMEOUT_S, write=10.0, pool=None), limits=httpx.Limits(max_connections=fetch_conc), ) + gpu_concurrency = max(1, _int_env("BGFILTER_GPU_CONCURRENCY", settings.server.gpu_concurrency)) logger.info( "starting bgfilter service: device=%s default_seg=%s cross_check=%s preload=%s " "cpu_workers=%d gpu_concurrency=%d max_pixels=%d auth=%s", @@ -208,10 +231,27 @@ async def lifespan(app: FastAPI): settings.cross_check.enabled, preload, cpu_workers, - max(1, _int_env("BGFILTER_GPU_CONCURRENCY", settings.server.gpu_concurrency)), + gpu_concurrency, MAX_IMAGE_PIXELS, "enabled" if AUTH_TOKEN else "DISABLED(open)", ) + # Same facts as a structured record on the access stream, so per-instance config + # is queryable next to the requests it served (no prose parsing). + _emit_access( + "startup", + { + "version": VERSION, + "device": settings.model.device, + "default_seg": settings.segmentation.backend, + "cross_check": settings.cross_check.enabled, + "reuse_as_seg": settings.cross_check.reuse_as_seg, + "preload": preload, + "cpu_workers": cpu_workers, + "gpu_concurrency": gpu_concurrency, + "max_pixels": MAX_IMAGE_PIXELS, + "auth": "enabled" if AUTH_TOKEN else "open", + }, + ) if not AUTH_TOKEN: logger.warning( "BGFILTER_AUTH_TOKEN not set: /remove-background is OPEN (no app-level auth)" @@ -244,13 +284,19 @@ async def _access_log_mw(request: Request, call_next): status = response.status_code response.headers["X-Request-ID"] = rid return response + except Exception: + # Unhandled escape (HTTPExceptions were already turned into responses by the + # inner exception middleware). setdefault: a more precise traceback recorded + # at the raise site wins over this generic one. + request.state.fields.setdefault("exc", traceback.format_exc()[-2000:]) + raise finally: if request.url.path != "/healthz": fields = {"request_id": rid, "client": request.client.host if request.client else "-"} fields.update(getattr(request.state, "fields", {}) or {}) fields["status"] = status fields["t_total_ms"] = round((time.perf_counter() - t0) * 1000) - _emit_access(fields) + _emit_access("request", fields) @app.get("/healthz") @@ -475,9 +521,11 @@ async def remove_background( detail="could not auto-detect background colour; pass screen_color", ) logger.exception("inference failed") + log["exc"] = traceback.format_exc()[-2000:] raise HTTPException(status_code=500, detail="inference failed") except Exception: logger.exception("inference failed") + log["exc"] = traceback.format_exc()[-2000:] raise HTTPException(status_code=500, detail="inference failed") elapsed_ms = int((time.perf_counter() - start) * 1000) log["t_process_ms"] = elapsed_ms diff --git a/scripts/deploy_autodl.sh b/scripts/deploy_autodl.sh index 5dce4fc..00a5371 100755 --- a/scripts/deploy_autodl.sh +++ b/scripts/deploy_autodl.sh @@ -15,9 +15,10 @@ # --open explicitly remove the token and run OPEN (no auth). # --port public-mapped container port (default 6006). # --config pipeline config (default configs/gpu.yaml). -# --log-dir directory for bgfilter.log (default ~/autodl-tmp, the AutoDL -# persistent data disk; unlike /tmp it survives container resets). -# File is /bgfilter.log. +# --log-dir log directory (default ~/autodl-tmp, the AutoDL persistent data +# disk; unlike /tmp it survives container resets). Holds +# bgfilter.log (prose event log, supervisord-captured) and +# bgfilter-access.jsonl (structured per-request log, app-rotated). # # Assumes: the repo is already checked out (this script does NOT git pull), root # user, torch/CUDA provided by the AutoDL image, python at /root/miniconda3. @@ -43,7 +44,7 @@ while [ $# -gt 0 ]; do --port) PORT="${2:-}"; shift 2;; --config) CONFIG="${2:-}"; shift 2;; --log-dir) LOG_DIR="${2:-}"; shift 2;; - -h|--help) sed -n '2,30p' "$0" | sed 's/^# \?//'; exit 0;; + -h|--help) sed -n '2,31p' "$0" | sed 's/^# \?//'; exit 0;; *) echo "unknown arg: $1" >&2; exit 1;; esac done @@ -112,8 +113,11 @@ cat > "$RUN_WRAPPER" <