feat(observability): 抓取去掉首页预热，交易补齐链路埋点

两个问题一起处理，都与「出站请求与可观测性」有关。 ## 抓取：正常路径不再多打一次首页 site_session 原先每条通道每 30 分钟打一次 www.rakuten.co.jp/ 做预热，而且预热返回非 2xx 时 warmed_at 不置位——那种情况下每个请求前都会再打一次首页。 Akamai 的 cookie 随任意页面响应下发，目标页自己就会带回来，专门先打一次首页除了多一个出站请求（以及多一次被风控计数的机会）之外没有额外收益：首个请求无论打哪个 URL 都是冷的 ~11s，之后都复用 cookie。改为 cookie 由目标页响应建立（_note_cookies）、超 TTL 主动清空（_drop_expired_cookies）。首页只保留在失败修复路径上（_rewarm_on_home）：目标页已经吃了挑战页时，拿首页换一套干净 cookie 比继续撞同一个 URL 更安全。happy path 的出站请求数 2 → 1。 _note_cookies 刻意不在每次响应时刷新时刻：TTL 要从「这套 cookie 第一次出现」算起，每次都刷新会让一套 cookie 被无限续命，反而绕过了 session_ttl_seconds 的本意。 profile_status() 的 warmed 字段名保留（上游健康检查看板在用），语义改为「当前有可复用的 Akamai cookie」，不再代表「已专门预热过首页」。 ## 交易：此前没有任何有意义的链路数据根因是 trading 的实际工作两类自动埋点都覆盖不到：站点交互走 Playwright（不经 httpx），worker 主循环是后台 asyncio 任务（没有 HTTP 入口，因此没有根 span）。于是发给网关的每次 httpx 调用各自成为孤立 trace——观测后台上只剩一堆请求记录。新增手工埋点： - order.task：一笔下单的根 span，一个 task_id 一条 trace，带 order.route （execute / recovery / already_finished）与终态 order.terminal_status - order.step.*：清车 → 加购 → 校验 → 确认 → 提交 → 付款，每步一个子 span，带 order.evidence_ref，可从 span 直接定位落盘证据 - site.*：12 个 Playwright 交互方法（用 traced 装饰器而非 with 块——这些方法的函数体本就很长，再加一层缩进不利于阅读） - account_query：只读查询单的根 span，带 query.outcome 空转的长轮询（30 秒一次、绝大多数返回空）用 suppressed() 屏蔽：量大且没有信息量，把观测后台刷满的正是它们。领到任务后的网关调用都在任务根 span 底下，不受影响。闸门 / 风控拦截会被 _execute_with_renewal 吞掉转 needs_human，异常冒不到根 span，被拦下的单在 trace 里跟成功下单一模一样。加 _execute_recording_errors 一层统一记录，比每个 except 分支各写一遍省事，也不会漏掉后续新增的分支。 _report_safe 写 span 属性前判断 is_recording()：付款后监控是 create_task 起的， asyncio 在创建时就把 context 复制了进去，等它真正跑起来根 span 早已结束—— get_current_span() 拿到的仍是那个已结束的 span（不是 INVALID_SPAN），写属性会打 "Setting attribute on ended span"。当前监控路径不传 terminal_status 走不到那里，这道判断是防以后。 ## 顺带修掉：instrument_app 从未生效 instrument_app 用 _provider is None 做前置判断，但三个服务都在模块导入时执行 app = create_app()，而 setup_telemetry 要等 lifespan 才跑——那时 _provider 还是 None，照着判断直接 return。**FastAPI 从来没被打桩过，三个服务一条 server span 都没有。** 实测确认两件事：导入期打桩能出 span，lifespan 内打桩出不来（instrument_app 是加中间件，应用开始服务后加进去不生效）；provider 后设也不影响 ProxyTracer 委托到真实 provider。所以只能在导入期装，判断条件改为 otel_enabled。 app/gateway/main.py 此前完全没接 telemetry，worker 出站请求带过来的 traceparent 没人接上，一条下单链路在网关这里断掉，只看得到 worker 侧那半截。补上 setup_telemetry(service_name="rakuten-gateway") 与 instrument_app / shutdown。 ## 验证新增 8 个用例：首页零请求、cookie 复用与过期清空、失败后用首页换 cookie、一任务一 trace 的父子结构、闸门失败标 ERROR、空转不埋点，以及 instrument_app 调用顺序的回归测试。全量 526 passed。 Playwright 那些 site.* 埋点只做了静态验证（测试用桩替换站点方法），没有跑真实浏览器下单确认 span 真的落地。 Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
2026-08-28 14:56:49 +08:00
parent bba45d7f7c
commit 3c7618a1d6
12 changed files with 727 additions and 113 deletions
@@ -21,8 +21,12 @@ import logging
 from datetime import datetime, timezone
 from typing import TYPE_CHECKING, Any

+from opentelemetry import trace
+from opentelemetry.trace import SpanKind
+
 from app.shared.errors import AppError, InvalidRequestError
 from app.shared.task_state import AccountQueryKind
+from app.shared.telemetry import record_error, set_attributes, suppressed
 from app.trading.worker.client import GatewayClient
 from app.trading.worker.models import QueryTask
 from app.trading.worker.site_interact import SiteInteractor
@@ -32,6 +36,8 @@ if TYPE_CHECKING:

 logger = logging.getLogger(__name__)

+tracer = trace.get_tracer(__name__)
+
 # 没给 since 时的窗口下界。用 epoch 而不是 None，是为了让翻页终止条件
 # （`order_date < since`）与「不设下界」共用同一条代码路径，不多一个分支。
 _EPOCH = datetime(1970, 1, 1, tzinfo=timezone.utc)
@@ -100,7 +106,9 @@ class QueryRunner:
        logger.info("账号查询 worker 启动：worker_id=%s", self.worker_id)
        while self._running:
            try:
-                query = await self._gateway.lease_query(self.worker_id, wait=30)
+                # 与下单主循环同样：空转的长轮询不埋点，见 runner.py::run
+                with suppressed():
+                    query = await self._gateway.lease_query(self.worker_id, wait=30)
            except AppError as exc:
                logger.warning("查询 lease 失败：%s (err=%s)", exc.message, exc.err_code)
                await asyncio.sleep(5)
@@ -122,7 +130,27 @@ class QueryRunner:
    # ---- 单张查询单 ----

    async def handle(self, query: QueryTask) -> None:
-        """执行一张查询单并回报结果。任何失败都转成一次「失败回报」，不抛出去"""
+        """执行一张查询单并回报结果。任何失败都转成一次「失败回报」，不抛出去
+
+        这里开的 span 是一张查询单的根：底下挂着站点读取（`site.*`）与回报网关的
+        HTTP 调用，一个 query_id 对应一条 trace。查询失败不抛出去（都转成失败
+        回报），所以失败信息由各分支显式记到 span 上——否则 trace 里会显示成功。
+        """
+        with tracer.start_as_current_span("account_query", kind=SpanKind.CONSUMER) as span:
+            set_attributes(
+                span,
+                {
+                    "query.query_id": query.query_id,
+                    "query.kind": query.kind,
+                    "query.site": query.site,
+                    "query.attempt": query.attempt,
+                    "query.worker_id": self.worker_id,
+                },
+            )
+            await self._handle_traced(query, span)
+
+    async def _handle_traced(self, query: QueryTask, span: "trace.Span") -> None:
+        """handle() 的实际执行体，拆出来只为让根 span 的 with 块保持一层缩进"""
        logger.info(
            "领到查询单：query_id=%s kind=%s attempt=%s",
            query.query_id, query.kind, query.attempt,
@@ -132,11 +160,13 @@ class QueryRunner:
                self.execute(query),
                timeout=self._settings.account_query_timeout_seconds,
            )
-        except asyncio.TimeoutError:
+        except asyncio.TimeoutError as exc:
            logger.warning(
                "查询超时（%s 秒，多半是下单任务正占着账号锁）：query_id=%s",
                self._settings.account_query_timeout_seconds, query.query_id,
            )
+            span.set_attribute("query.outcome", "timeout")
+            record_error(span, exc)
            await self._report_safe(
                query,
                success=False,
@@ -152,12 +182,16 @@ class QueryRunner:
                "查询失败：query_id=%s code=%s msg=%s",
                query.query_id, exc.err_code, exc.message,
            )
+            span.set_attribute("query.outcome", "failed")
+            record_error(span, exc)
            await self._report_safe(
                query, success=False, error_code=exc.err_code, error_message=exc.message
            )
            return
        except Exception as exc:  # noqa: BLE001
            logger.exception("查询未预期异常：query_id=%s", query.query_id)
+            span.set_attribute("query.outcome", "unexpected_error")
+            record_error(span, exc)
            await self._report_safe(
                query,
                success=False,
@@ -168,10 +202,12 @@ class QueryRunner:

        payload, oversized = self._enforce_result_size(result)
        if oversized is not None:
+            span.set_attribute("query.outcome", "oversized")
            await self._report_safe(
                query, success=False, error_code=1003, error_message=oversized
            )
            return
+        span.set_attribute("query.outcome", "succeeded")
        await self._report_safe(query, success=True, result=payload)

    async def execute(self, query: QueryTask) -> dict[str, Any]:
@@ -28,6 +28,9 @@ import contextlib
 import logging
 from typing import TYPE_CHECKING

+from opentelemetry import trace
+from opentelemetry.trace import SpanKind, Status, StatusCode
+
 from app.shared.errors import (
    AppError,
    BrowserDeadError,
@@ -35,6 +38,7 @@ from app.shared.errors import (
    OrderGuardError,
 )
 from app.shared.task_state import OrderState, TaskStatus
+from app.shared.telemetry import record_error, set_attributes, suppressed
 from app.trading.worker import verify
 from app.trading.worker.client import GatewayClient
 from app.trading.worker.evidence import EvidenceStore
@@ -47,6 +51,8 @@ if TYPE_CHECKING:

 logger = logging.getLogger(__name__)

+tracer = trace.get_tracer(__name__)
+

 def _coerce_state(value: str | None) -> OrderState:
    """把网关返回的 state 字符串安全地包成 OrderState；None 或非法值回落到 CREATED"""
@@ -115,7 +121,11 @@ class WorkerRunner:
        logger.info("worker 启动：worker_id=%s", self.worker_id)
        while self._running:
            try:
-                task = await self._gateway.lease(self.worker_id, wait=30)
+                # 空转的长轮询不埋点：30 秒一次、绝大多数返回空，每次都会变成一条
+                # 孤立 trace 把观测后台刷满。领到任务后的调用都在 handle() 的根
+                # span 底下，不受这里影响。
+                with suppressed():
+                    task = await self._gateway.lease(self.worker_id, wait=30)
            except AppError as exc:
                logger.warning("lease 失败：%s (err=%s)", exc.message, exc.err_code)
                await asyncio.sleep(5)
@@ -137,13 +147,42 @@ class WorkerRunner:
    # ---- 单任务调度 ----

    async def handle(self, task: LeaseTask) -> None:
-        """单任务调度入口：本地幂等闸门 → 恢复核对 → 执行"""
+        """单任务调度入口：本地幂等闸门 → 恢复核对 → 执行
+
+        这里开的 span 是**整条下单链路的根**：往下的每一步站点交互、每一次回报
+        网关都挂在它底下，一个 task_id 对应观测后台里的一条 trace。worker 是后台
+        asyncio 任务，没有 HTTP 入口，不开这个根 span 的话下游 httpx 调用会各自
+        散成孤立 trace（这正是「只有请求记录、没有链路」的原因）。
+        """
+        with tracer.start_as_current_span("order.task", kind=SpanKind.CONSUMER) as span:
+            intent = task.intent or {}
+            set_attributes(
+                span,
+                {
+                    "order.task_id": task.task_id,
+                    "order.site": task.site,
+                    "order.worker_id": self.worker_id,
+                    "order.lease_count": task.lease_count,
+                    "order.known_state": task.known_state,
+                    "order.item_url": intent.get("item_url"),
+                    "order.quantity": intent.get("quantity"),
+                },
+            )
+            try:
+                await self._dispatch(task, span)
+            except Exception as exc:
+                record_error(span, exc)
+                raise
+
+    async def _dispatch(self, task: LeaseTask, span: "trace.Span") -> None:
+        """handle() 的实际分支逻辑，拆出来只为让根 span 的 with 块保持一层缩进"""
        # 本地幂等闸门：之前已完成过的任务不再执行
        if await self._db.has_finished(task.task_id):
            final_state = await self._db.final_state(task.task_id)
            logger.info(
                "本地已完成，补报终态：task_id=%s state=%s", task.task_id, final_state
            )
+            span.set_attribute("order.route", "already_finished")
            await self._report_safe(
                task,
                state=_coerce_state(final_state),
@@ -154,10 +193,12 @@ class WorkerRunner:

        # 恢复领取：lease_count > 1 表示 stale → reclaim，必须先核对站点订单
        if task.lease_count > 1:
+            span.set_attribute("order.route", "recovery")
            await self._handle_recovery(task)
            return

        # 常规执行
+        span.set_attribute("order.route", "execute")
        await self._execute_with_renewal(task)

    async def _handle_recovery(self, task: LeaseTask) -> None:
@@ -197,11 +238,24 @@ class WorkerRunner:

    # ---- 常规执行 ----

+    async def _execute_recording_errors(self, task: LeaseTask) -> None:
+        """execute() 外面加一层：异常先记到任务根 span 上，再原样抛出
+
+        下面那一串 except 分支会把异常**吞掉**转成 needs_human / failed 回报，
+        异常冒不到 handle() 的根 span。在这里统一记一次，比每个分支各写一遍省事，
+        也不会漏掉新增的分支。
+        """
+        try:
+            await self.execute(task)
+        except Exception as exc:
+            record_error(trace.get_current_span(), exc)
+            raise
+
    async def _execute_with_renewal(self, task: LeaseTask) -> None:
        """在租约自动续期的上下文里执行任务"""
        async with self._renew_lease_every(task, interval=60):
            try:
-                await self.execute(task)
+                await self._execute_recording_errors(task)
            except NotImplementedError as exc:
                # 站点交互未实现（规格 §10）：上报 needs_human，不视为 worker 失败
                logger.warning(
@@ -521,38 +575,65 @@ class WorkerRunner:
        证据载体）时，其 html / screenshot 即本步骤要落盘的页面与整页截图；
        显式传入的 `html` / `png` 优先级更高，供 step3/step4 等已经单独拿到
        页面的调用点使用。
+
+        每步一个 span，挂在 handle() 的任务根 span 底下：一条 trace 就是一单的
+        完整流水（清车 → 加购 → 校验 → 确认 → 提交 → 付款），卡在哪一步、每步
+        耗时多少、证据落在哪个 evidence_ref 都能直接读出来。
        """
-        result = await action()
-        if isinstance(result, PageSnapshot):
-            if html is None:
-                html = result.html or None
-            if png is None:
-                png = result.screenshot or None
-        elif html is None and isinstance(result, str):
-            # 旧契约兼容：站点方法返回字符串时视为页面 HTML
-            html = result
-        meta = {
-            "step": step_name,
-            "state": state.value,
-            **(evidence_meta or {}),
-        }
-        evidence_ref = self._evidence.write_step(
-            task.task_id, step_no, step_name, html=html, png=png, meta=meta
-        )
-        await self._db.index_evidence(task.task_id, step_no, step_name, evidence_ref)
-        await self._db.record_event(
-            task.task_id, state.value, detail=detail, evidence_ref=evidence_ref
-        )
-        await self._gateway.report(
-            task.task_id,
-            self.worker_id,
-            state=state,
-            payable_yen=payable_yen,
-            pay_deadline=pay_deadline,
-            site_order_id=site_order_id,
-            evidence_ref=evidence_ref,
-            detail=detail,
-        )
+        with tracer.start_as_current_span(f"order.step.{step_name}") as span:
+            set_attributes(
+                span,
+                {
+                    "order.task_id": task.task_id,
+                    "order.step_no": step_no,
+                    "order.step_name": step_name,
+                    "order.state": state.value,
+                },
+            )
+            try:
+                result = await action()
+            except Exception as exc:
+                record_error(span, exc)
+                raise
+
+            if isinstance(result, PageSnapshot):
+                if html is None:
+                    html = result.html or None
+                if png is None:
+                    png = result.screenshot or None
+            elif html is None and isinstance(result, str):
+                # 旧契约兼容：站点方法返回字符串时视为页面 HTML
+                html = result
+            meta = {
+                "step": step_name,
+                "state": state.value,
+                **(evidence_meta or {}),
+            }
+            evidence_ref = self._evidence.write_step(
+                task.task_id, step_no, step_name, html=html, png=png, meta=meta
+            )
+            set_attributes(
+                span,
+                {
+                    "order.evidence_ref": evidence_ref,
+                    "order.site_order_id": site_order_id,
+                    "order.payable_yen": payable_yen,
+                },
+            )
+            await self._db.index_evidence(task.task_id, step_no, step_name, evidence_ref)
+            await self._db.record_event(
+                task.task_id, state.value, detail=detail, evidence_ref=evidence_ref
+            )
+            await self._gateway.report(
+                task.task_id,
+                self.worker_id,
+                state=state,
+                payable_yen=payable_yen,
+                pay_deadline=pay_deadline,
+                site_order_id=site_order_id,
+                evidence_ref=evidence_ref,
+                detail=detail,
+            )

    async def _report_safe(
        self,
@@ -566,7 +647,25 @@ class WorkerRunner:
        payable_yen: int | None = None,
        pay_deadline: str | None = None,
    ) -> None:
-        """回报 gateway，失败只记日志不抛——主循环不能因为回报失败退出"""
+        """回报 gateway，失败只记日志不抛——主循环不能因为回报失败退出
+
+        顺带把终态标到当前 span 上。这一步是必要的：`_execute_with_renewal` 会把
+        闸门拦截、风控拦截、浏览器掉线等异常**吞掉**转成 needs_human 回报，异常
+        不会冒到 handle() 的根 span，于是一笔被拦下的单在 trace 里看起来跟成功
+        下单一模一样。所有这些分支都汇到这个方法，标在这里最省事也最不容易漏。
+
+        `is_recording()` 那道判断不是多余的：付款后监控（_monitor_order）是
+        `create_task` 起的后台任务，而 asyncio 在创建时就把当时的 context 复制了
+        进去——等它真正跑起来，任务根 span 早已结束，但 `get_current_span()` 拿到
+        的仍是那个**已结束**的 span（不是 INVALID_SPAN）。往上写属性会打
+        "Setting attribute on ended span" 警告。当前监控路径不传 terminal_status
+        走不到这里，但这道判断保证以后传了也不会污染已完成的任务 span。
+        """
+        span = trace.get_current_span()
+        if terminal_status is not None and span.is_recording():
+            span.set_attribute("order.terminal_status", terminal_status.value)
+            if terminal_status in (TaskStatus.NEEDS_HUMAN, TaskStatus.FAILED):
+                span.set_status(Status(StatusCode.ERROR, detail))
        try:
            await self._gateway.report(
                task.task_id,
@@ -96,6 +96,8 @@ from dataclasses import dataclass, field
 from datetime import datetime
 from typing import TYPE_CHECKING, TypeVar

+from opentelemetry.trace import SpanKind
+
 from app.shared.errors import (
    BrowserDeadError,
    CartOperationError,
@@ -113,6 +115,8 @@ from app.shared.purchase_contract import (
 )
 from app.shared.proxy import playwright_launch_proxy
 from app.shared.task_state import OrderState
+from app.shared.telemetry import traced
+
 from app.trading.core import auth_site
 from app.trading.worker.models import LeaseTask

@@ -973,6 +977,7 @@ class SiteInteractor:

    # ---- 已实现：add_to_cart / verify_cart / cart_status ----

+    @traced("site.add_to_cart", kind=SpanKind.CLIENT)
    async def add_to_cart(self, task: LeaseTask) -> PageSnapshot:
        """加购（worker 入口）：从 task.intent 取字段，调 _add_to_cart_with_fields

@@ -1015,6 +1020,7 @@ class SiteInteractor:
            screenshot=result.get("screenshot") or b"",
        )

+    @traced("site.add_to_cart_payload", kind=SpanKind.CLIENT)
    async def add_to_cart_payload(
        self,
        *,
@@ -1163,6 +1169,7 @@ class SiteInteractor:
            "screenshot": screenshot,
        }

+    @traced("site.verify_cart", kind=SpanKind.CLIENT)
    async def verify_cart(self, task: LeaseTask) -> PageSnapshot:
        """校验购物车里有没有刚加的商品

@@ -1196,6 +1203,7 @@ class SiteInteractor:
            # 2. 渲染 cart 页确认 item_id 在里面
            return await self._verify_item_in_cart_html(item_id, label=f"task_id={task.task_id}")

+    @traced("site.cart_status", kind=SpanKind.CLIENT)
    async def cart_status(self) -> dict:
        """轻量查询购物车状态：调 cart count JSONP API，不渲染整页

@@ -1216,6 +1224,7 @@ class SiteInteractor:

    # ---- 已实现：clear_cart / remove_item（Playwright UI 点击）----

+    @traced("site.clear_cart", kind=SpanKind.CLIENT)
    async def clear_cart(self) -> dict:
        """清空购物车：渲染 cart SPA → 反复点第一个「削除」按钮 → count API 校验

@@ -1304,6 +1313,7 @@ class SiteInteractor:
                "screenshot": screenshot,
            }

+    @traced("site.remove_item", kind=SpanKind.CLIENT)
    async def remove_item(self, item_id: str) -> dict:
        """删除购物车里指定 item_id 的商品

@@ -1506,6 +1516,7 @@ class SiteInteractor:

    # ---- 已实现：enter_checkout（到下单确认页，中间步骤未经真实 HTML 验证）----

+    @traced("site.enter_checkout", kind=SpanKind.CLIENT)
    async def enter_checkout(self, task: LeaseTask) -> PageSnapshot:
        """进入下单确认页：购物车 → 点「購入手続き」→ 依次处理中间步骤 → 落地确认页

@@ -2017,6 +2028,7 @@ class SiteInteractor:
        """
        return _parse_checkout_summary(html)

+    @traced("site.submit_order", kind=SpanKind.CLIENT)
    async def submit_order(self, task: LeaseTask) -> SubmitOutcome:
        """点击下单确认页的最终确认按钮，提交订单

@@ -2118,6 +2130,7 @@ class SiteInteractor:
                evidence=PageSnapshot(html=html, screenshot=screenshot),
            )

+    @traced("site.pay", kind=SpanKind.CLIENT)
    async def pay(self, task: LeaseTask, site_order_id: str) -> PageSnapshot:
        """检查提交下单后是否已完成付款 / 是否触发了需要人工介入的验证环节

@@ -2181,6 +2194,7 @@ class SiteInteractor:
                except Exception:
                    logger.debug("pay 关闭确认页失败", exc_info=True)

+    @traced("site.check_order_status", kind=SpanKind.CLIENT)
    async def check_order_status(self, site_order_id: str) -> OrderStatusSnapshot:
        """付款后监控的单次探测：查一次订单详情页的配送阶段，不循环

@@ -2198,6 +2212,7 @@ class SiteInteractor:
        """
        return (await self.fetch_order_detail(site_order_id)).status

+    @traced("site.fetch_order_detail", kind=SpanKind.CLIENT)
    async def fetch_order_detail(self, site_order_id: str) -> OrderDetailSnapshot:
        """读一次订单详情页：配送阶段 + 页面原始 __INITIAL_STATE__

@@ -2269,6 +2284,7 @@ class SiteInteractor:
            f"check_order_status site_order_id={site_order_id}", read
        )

+    @traced("site.list_recent_orders", kind=SpanKind.CLIENT)
    async def list_recent_orders(
        self, *, since: datetime, max_pages: int | None = None
    ) -> OrderListWindow: