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 <noreply@anthropic.com>
2026-07-17 13:40:33 +00:00
parent 3a8a1ef38a
commit 43797eedeb
4 changed files with 98 additions and 35 deletions
@@ -40,7 +40,7 @@ Arguments:
 | `--open` | — | Explicitly remove the token and run OPEN (no auth). |
 | `--port <PORT>` | `6006` | In-container listen port (matches the AutoDL public port mapping). |
 | `--config <cfg>` | `configs/gpu.yaml` | Pipeline config. |
-| `--log-dir <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 <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
@@ -34,7 +34,7 @@ scripts/deploy_autodl.sh --token <TOKEN>
 | `--open` | — | 显式删除 token、以开放模式运行（无鉴权）。 |
 | `--port <PORT>` | `6006` | 容器内监听端口（对应 AutoDL 的公网映射端口）。 |
 | `--config <cfg>` | `configs/gpu.yaml` | 流水线配置。 |
-| `--log-dir <dir>` | `~/autodl-tmp` | 服务日志 `bgfilter.log` 所在目录。默认落在 AutoDL 持久数据盘 `~/autodl-tmp`（容器重置不丢），而非 `/tmp`。 |
+| `--log-dir <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
@@ -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
@@ -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 <dir>/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" <<WRAP
 #!/bin/bash
 cd "$APP_DIR" || exit 1
 export BGFILTER_CONFIG="$CONFIG"
+export BGFILTER_ACCESS_LOG="$LOG_DIR/bgfilter-access.jsonl"
 [ -f "$TOKEN_FILE" ] && export BGFILTER_AUTH_TOKEN="\$(cat "$TOKEN_FILE")"
-exec "$PY" -m uvicorn app:app --host 0.0.0.0 --port $PORT --workers 1
+# --no-access-log: uvicorn's prose per-request lines would duplicate (a subset of)
+# the app's structured access records -- per-request data stays out of the prose log.
+exec "$PY" -m uvicorn app:app --host 0.0.0.0 --port $PORT --workers 1 --no-access-log
 WRAP
 chmod +x "$RUN_WRAPPER"