fix(capture): 读不到源行时按日志年龄延迟重试，根治降级Delete致数据丢失

Insert/Update 日志回读不到源行时，旧逻辑无条件降级为 Delete，在 ACE
引擎可见性延迟（批量插入约11s窗口）下误伤，导致该 Insert 的行不仅没进
SQL 反而被空打 Delete 并清理 Access 日志，数据永久丢失（8/4 事件根因：
氩弧焊.接收 16255-16259 缺失）。

改为按 Access 日志年龄（capture_defer_seconds=60）决定动作：
- 年龄 < 阈值：DEFER，跳过不入队，Access 日志保留，下一轮 cycle 重读；
- 年龄 >= 阈值：AGED-OUT，入队直接标 dead 待人工（usp_SyncApply 只选
  pending，不会执行任何破坏性 SQL），归档表记 ProcessedOperateType=AgedOut。

零 schema/SQL 改动：cleanup 只删 Status=applied 的日志，DEFER 行不入队
则无 applied 行、AGED-OUT 标 dead 非 applied，两者 Access 日志均保留，
与既有 cleanup/apply/service 逻辑天然自洽。

详见 docs/plan-capture-defer-by-age.md 与 docs/incremental-sync-flow.md。

docs/incremental-sync-flow.md

@@ -0,0 +1,281 @@
+# 增量同步流程详解（Incremental Sync Flow）
+
+> 本文档梳理 Access → SQL Server 增量同步的完整流程，逐节点说明「发生了什么、读了/写了什么、状态如何流转」，作为重构「Insert 降级 Delete」逻辑的决策依据。
+>
+> 涉及代码：`src/sync/service.py`（主循环 cycle）、`src/sync/capture.py`（捕获）、`sql/02_sync_apply.sql`（应用）、`src/sync/cleanup.py`（清理）、`src/sync/sql_writer.py`（SQL 端读写）、`src/sync/access_reader.py`（Access 端读取）。
+
+---
+
+## 一、整体架构：一轮 cycle 的三段流水线
+
+每个 cycle（默认间隔 `poll_interval_seconds=10s`）跑一遍三段，顺序固定、不可调换：
+
+```mermaid
+flowchart TD
+    START([cycle 开始<br/>分配 cycle_id]) --> CAP
+
+    CAP["【1. Capture 捕获】<br/>逐库读 TableChangeLog → 回读整行 → 入队 SyncQueue<br/><i>src/sync/capture.py</i>"]
+    CAP --> APPLY
+
+    APPLY["【2. Apply 应用】<br/>调 usp_SyncApply 把 SyncQueue pending 行落到镜像表<br/><i>sql/02_sync_apply.sql</i>"]
+    APPLY --> HEALTH
+
+    HEALTH["【2.5 队列健康检查】<br/>查 error/dead 卡死行并告警"]
+    HEALTH --> CLEAN
+
+    CLEAN["【3. Cleanup 清理】<br/>删 Access 已应用日志 → SyncQueue 行标 cleaned<br/><i>src/sync/cleanup.py</i>"]
+    CLEAN --> PURGE
+
+    PURGE["【3.5 Purge 回收】<br/>删 SyncQueue 中超保留期的 cleaned 行"]
+    PURGE --> DONE([cycle 结束<br/>休眠 poll_interval])
+
+    style CAP fill:#e3f2fd,stroke:#1976d2
+    style APPLY fill:#fff3e0,stroke:#f57c00
+    style HEALTH fill:#fce4ec,stroke:#c2185b
+    style CLEAN fill:#e8f5e9,stroke:#388e3c
+    style PURGE fill:#f3e5f5,stroke:#7b1fa2
+```
+
+**关键设计约束**（决定重构可行性的红线）：
+- **Access 的 `TableChangeLog` 是 append-only，无状态字段**——它只是个待处理队列，无法在上面记录「已重试几次」。
+- **日志清除的唯一依据是 SyncQueue 的 `Status='applied'`**——只要一条日志对应的队列行不是 applied，cleanup 就不会删它（详见第三节）。
+- **SyncQueue 有唯一索引 `(SourceFile,SourceTable,SourceLogID)` 去重**——同一日志第二次入队会被静默跳过，不会覆盖原行、不会自增计数。
+
+---
+
+## 二、Capture 阶段（数据捕获）—— ❗重构的核心战场
+
+逐库处理，每个 Access 文件独立隔离（单库失败不影响其它）。
+
+```mermaid
+flowchart TD
+    A([开始 capture 某个文件]) --> B["读 Access TableChangeLog<br/>最旧 N 条（按 ID 升序）<br/>N = capture_batch_size=500"]
+    B --> C{有日志行?}
+    C -- 否 --> Z([capture 结束])
+    C -- 是 --> D[逐行处理]
+
+    D --> E{"表是否在同步范围内?<br/>is_synced_table"}
+    E -- 否 --> F["跳过（out_of_scope）<br/>不计入，下轮仍会读到"]
+    F --> D
+    E -- 是 --> G{"OperateType?"}
+
+    G -- Insert/Update --> H["🔑 回读整行<br/>read_row(table, record_id)<br/>SELECT * FROM 表 WHERE ID=?"]
+    H --> I{读到行?}
+    I -- 是 --> J["row_data = JSON 序列化<br/>op 保持 Insert/Update"]
+    I -- ❌否 --> K["⚠️ 降级 op = Delete<br/>row_data = None<br/>写 DOWNGRADE 警告日志"]
+
+    G -- Delete --> L["op = Delete<br/>row_data = None<br/>（不回读，Delete 无需数据）"]
+
+    G -- 其它未知 --> M["跳过（unknown_op）<br/>下轮仍会读到"]
+
+    J --> N["写 SyncLogArchive（永久审计）<br/>记录 OriginalOperateType + ProcessedOperateType"]
+    K --> N
+    L --> N
+
+    N --> O["入队 SyncQueue（去重插入）<br/>INSERT...WHERE NOT EXISTS"]
+    O --> P{插入成功?}
+    P -- 是 --> Q["enqueued +1"]
+    P -- 否（去重命中）--> R["dedup_skipped +1<br/>说明上轮 apply 失败残留"]
+
+    Q --> S{还有下一行?}
+    R --> S
+    F --> S
+    M --> S
+    S -- 是 --> D
+    S -- 否 --> T["打印 capture summary<br/>read/enqueued/downgraded/..."]
+    T --> Z
+
+    style K fill:#ffcdd2,stroke:#c62828,stroke-width:3px
+    style H fill:#fff9c4,stroke:#f9a825
+    style I fill:#fff9c4,stroke:#f9a825
+```
+
+### 🔴 问题节点：降级 Delete（`capture.py:93-108`）
+
+```python
+if op in ("Insert", "Update"):
+    d = reader.read_row(lr.table_name, lr.record_id)
+    if d is None:
+        op = "Delete"          # ← 问题根源：读不到就降级
+        st.downgraded += 1
+        log.warning("capture DOWNGRADE %s->Delete ...")
+```
+
+**为什么读不到？两个场景无法区分：**
+1. **真删除**：行被 Insert 后又 Delete（Access 客户端先插后删）→ 这时降级 Delete 是「碰巧正确」。
+2. **可见性延迟**（本次事件的根因）：行已插入但 ACE 引擎尚未对其他 ODBC 连接可见（批量插入时窗口可达 11 秒）→ 这时降级 Delete 是**有害的误伤**。
+
+**代码当前无法区分这两种情况**，统一降级为 Delete。这就是要重构的核心。
+
+---
+
+## 三、Apply 阶段（数据应用）
+
+调用存储过程 `usp_SyncApply`，**按表分组、集合化处理**所有 pending 行。
+
+```mermaid
+flowchart TD
+    A([call_apply<br/>EXEC usp_SyncApply]) --> B["重置 error 行<br/>RetryCount < max_retries 的 → pending"]
+    B --> C["按 TargetSchema+TargetTable 分组<br/>遍历每个目标表"]
+
+    C --> D{该表有 pending 行?}
+    D -- 否 --> C
+    D -- 是 --> E["统计 pending 数 / distinct RecordID 数"]
+
+    E --> F["BEGIN TRAN"]
+
+    F --> G["🔑 构建列清单<br/>从 sys.columns 读目标表所有列<br/>（排除 ID/computed/identity/timestamp）"]
+
+    G --> H["构建动态 SQL"]
+
+    H --> I["分支1: Upsert（MERGE）<br/>ranked CTE: 按 RecordID 分区,<br/>SourceLogID DESC 取 rn=1<br/>仅 OperateType∈Insert/Update 且 RowData 非空"]
+    I --> J["SET IDENTITY_INSERT ON<br/>MERGE 目标表<br/>匹配则 UPDATE, 不匹配则 INSERT<br/>@merged = @@ROWCOUNT"]
+
+    J --> K["分支2: Delete<br/>同一 ranked CTE 的 rn=1 行<br/>仅 OperateType=Delete"]
+    K --> L["DELETE 目标表 WHERE ID IN (...)<br/>@deleted = @@ROWCOUNT"]
+
+    L --> M["把该表所有 pending 行<br/>Status → applied, AppliedAt = now<br/>@applied = @@ROWCOUNT"]
+
+    M --> N[COMMIT]
+
+    N --> O["写 SyncApplyRunLog 审计<br/>pending/merged/deleted/applied/<br/>error/dead + CycleID + 耗时"]
+    O --> C
+
+    N -.失败.-> X["ROLLBACK"]
+    X --> Y["超 max_retries → dead<br/>否则 → error（下轮重试）"]
+    Y --> O
+
+    style I fill:#e3f2fd,stroke:#1976d2
+    style K fill:#ffcdd2,stroke:#c62828
+    style M fill:#fff3e0,stroke:#f57c00
+```
+
+### 关键：保序「最后操作胜」（`02_sync_apply.sql:95-135`）
+
+单个 `ranked` CTE 同时供 Upsert 和 Delete 两个分支使用：
+```sql
+ROW_NUMBER() OVER (PARTITION BY RecordID ORDER BY SourceLogID DESC) rn
+```
+- `rn=1` 是该 RecordID **真正的最后一条日志**。
+- Upsert 分支：`rn=1 AND OperateType IN ('Insert','Update')`
+- Delete 分支：`rn=1 AND OperateType='Delete'`
+
+所以**降级成 Delete 的行，在这里会真的去 SQL 端执行 DELETE**。本次事件中 5 行 Delete 的 `@deleted=0`（SQL 里本就没这些行，空打），但 `@applied=5`（队列行照样被标 applied）。
+
+---
+
+## 四、Cleanup 阶段（日志清除）—— ❗决定「重试」能否成立的命脉
+
+```mermaid
+flowchart TD
+    A([cleanup 某个文件]) --> B["查 SyncQueue 中<br/>Status=applied 的 SourceLogID 列表<br/>applied_log_ids(file)"]
+    B --> C{有 applied 行?}
+    C -- 否 --> Z([cleanup 结束, 返回 0])
+    C -- 是 --> D["DELETE FROM Access.TableChangeLog<br/>WHERE ID IN (上述列表)<br/>分批 + 锁重试"]
+    D --> E{删除数 == 预期?}
+    E -- 否 --> F["WARNING: 部分日志已不在<br/>（被外部或中断的运行删过）"]
+    E -- 是 --> G["mark_cleaned:<br/>这些队列行 Status → cleaned<br/>CleanedAt = now"]
+    F --> G
+    G --> H["INFO: 删除了 N 条 Access 日志"]
+    H --> Z
+
+    style D fill:#e8f5e9,stroke:#388e3c,stroke-width:2px
+    style B fill:#fff9c4,stroke:#f9a825
+```
+
+### 🔑 cleanup 的判定条件是重构的支点
+
+**cleanup 只删 `Status='applied'` 的日志**（`sql_writer.py:264-272` 的 `applied_log_ids`）。这意味着：
+
+| capture 对该日志的处理 | SyncQueue 行状态 | cleanup 是否删 Access 日志 | 后果 |
+|------------------------|------------------|----------------------------|------|
+| 降级 Delete（现状） | applied | **删除** | ❌ 日志消失，再无重试机会 |
+| **跳过不入队（重构后）** | （无对应行） | **不删** | ✅ 日志保留，下轮重读 |
+
+**结论：重构只要做到「读不到 → 不入队」，cleanup 这一段天然会把日志保留下来，无需改动 cleanup.py。** 这是「跨 cycle 重试」能够成立的根基。
+
+---
+
+## 五、数据流转全景：一条日志的完整生命周期
+
+```mermaid
+flowchart LR
+    subgraph Access["Access 端（.accdb）"]
+        T1[(业务表<br/>如 接收)]
+        TCL[(TableChangeLog<br/>变更日志 append-only)]
+    end
+
+    subgraph SQL["SQL Server 端（CompanyDB）"]
+        SQ[(SyncQueue<br/>待处理队列)]
+        ARCH[(SyncLogArchive<br/>永久审计)]
+        RL[(SyncApplyRunLog<br/>apply 运行日志)]
+        MIRROR[(镜像表<br/>如 接收_YEAR2026)]
+    end
+
+    T1 -- "数据宏 After I/U/D<br/>写入一行日志" --> TCL
+    TCL -- "① capture 读取" --> CAP[Capture]
+    CAP -- "回读整行" --> T1
+    CAP -- "② 入队（去重）" --> SQ
+    CAP -- "② 审计存档" --> ARCH
+    SQ -- "③ apply 处理" --> APPLY[usp_SyncApply]
+    APPLY -- "MERGE/DELETE" --> MIRROR
+    APPLY -- "pending→applied" --> SQ
+    APPLY -- "记录运行结果" --> RL
+    SQ -- "④ cleanup 查 applied" --> CLEAN[Cleanup]
+    CLEAN -- "⑤ 删已应用日志" --> TCL
+    CLEAN -- "applied→cleaned" --> SQ
+
+    style CAP fill:#e3f2fd,stroke:#1976d2
+    style APPLY fill:#fff3e0,stroke:#f57c00
+    style CLEAN fill:#e8f5e9,stroke:#388e3c
+```
+
+---
+
+## 六、本次事件的重放（在上述流程中的路径）
+
+5 条 Insert 日志（RecordID 16255-16259）在一轮 cycle 中的遭遇：
+
+```mermaid
+flowchart TD
+    A["8/3 09:01 Access 批量插入 5 行<br/>数据宏写 5 条 Insert 日志<br/>SourceLogID 15533-15537"] --> B
+
+    B["09:00:50 Capture 读取这 5 条日志<br/>（注: CapturedAt 比 OriginalTime 早 11s<br/> = ACE 可见性窗口）"] --> C
+
+    C["read_row 回读 5 行<br/>SELECT * FROM 接收 WHERE ID=16255..16259"] --> D
+
+    D["❌ 全部返回 None<br/>（行尚未对其他连接可见）"] --> E
+
+    E["🔴 降级为 Delete<br/>入队 SyncQueue, OperateType=Delete<br/>RowData=null"] --> F
+
+    F["09:00:51 Apply: Delete 分支<br/>DELETE 接收_YEAR2026 WHERE ID IN(16255..16259)<br/>@deleted=0（SQL 本就没这5行）<br/>@applied=5（队列行标 applied）"] --> G
+
+    G["队列行 Status = applied"] --> H
+
+    H["Cleanup: 查到这5条 applied<br/>DELETE Access.TableChangeLog ID=15533-15537"] --> I
+
+    I["🔴 日志被删，5 条 Insert 证据消失<br/>这5行从此再无机会被同步进 SQL"] --> J
+
+    J["8/4 05:08 compare: missing_in_sql=5<br/>ID 16255-16259"]
+
+    style D fill:#ffcdd2,stroke:#c62828
+    style E fill:#ffcdd2,stroke:#c62828,stroke-width:3px
+    style H fill:#e8f5e9,stroke:#388e3c
+    style I fill:#ffcdd2,stroke:#c62828
+    style J fill:#fff9c4,stroke:#f9a825
+```
+
+**链式灾难**：降级 Delete（capture）→ 空打 Delete 但标 applied（apply）→ 删 Access 日志（cleanup）。三段配合下，这 5 行被「合法地」从同步链路中抹除。只要在 capture 段断开第一环（不降级、不入队），后面 apply/cleanup 就不会碰它们，日志保留，下轮自然重试。
+
+---
+
+## 七、重构决策点（待定）
+
+基于上述流程，重构的核心是改造 capture 阶段的「降级」分支。需要决策的问题：
+
+1. **读不到时的动作**：跳过不入队（日志保留，下轮重读）vs 入队但标记 defer 状态？
+2. **重试上限的判定依据**：用「重试次数」（需要存储计数）vs 用「日志年龄时间窗」（无需存储，靠 `now - OriginalTime > 阈值`）？
+3. **终态处理**：超限后该 Access 日志保留（占队列头持续重读）还是删除（丢证据）？
+4. **Update 日志**：是否套用同一套 defer 逻辑？
+
+我倾向的方案：**读不到 → 不入队 + 写 defer 审计；用日志年龄（如 120s）作终态判据；超限则入队标 dead（保留 Access 日志不删，待人工）**。零 schema 改动、零状态存储。等你审完这份流程图确认方向后，我再动手。

docs/plan-capture-defer-by-age.md

@@ -0,0 +1,211 @@
+# 重构方案：capture 读不到行时按「日志年龄」延迟重试
+
+> 目标：根治「Insert 日志回读不到行 → 降级 Delete → 数据丢失」的缺陷（8/4 事件根因）。
+> 核心改动：读不到 → **不入队、不降级**，按 Access 日志的年龄决定「下轮重试」还是「判死待人工」。
+> 改动面：`capture.py`（主）、`config.py`（新增2个配置项）、`capture.py` 的 CaptureStats（新增计数器）。**零 schema 改动、零 SQL 改动、不动 apply/cleanup。**
+
+---
+
+## 一、当前问题行为 vs 重构后行为
+
+| 场景 | 当前行为（缺陷） | 重构后行为 |
+|------|------------------|-----------|
+| Insert/Update 读不到行（可见性延迟，本次事件） | 降级 Delete → 入队 → apply 空打 Delete + 标 applied → cleanup 删 Access 日志 → **数据永久丢失** | 年龄 < 阈值：跳过不入队，日志保留，下轮重读 → 读到后正常 Insert ✅ |
+| Insert/Update 读不到行（真删除：先插后删） | 降级 Delete（碰巧正确） | 年龄 < 阈值：跳过；后续 Delete 日志会兜底正确清理；超龄判死待人工 ✅ |
+| Insert/Update 一直读不到（真异常/数据损坏） | 降级 Delete（错误） | 年龄 ≥ 阈值：入队标 dead，保留 Access 日志，**告警待人工** ✅ |
+
+---
+
+## 二、配置项新增（`src/sync/config.py` 的 RuntimeConfig）
+
+```python
+class RuntimeConfig(BaseModel):
+    # ... 既有字段 ...
+    # Insert/Update 日志回读不到行时，按日志年龄延迟重试：年龄小于此秒数则
+    # 跳过不入队（保留 Access 日志，下一轮 cycle 重新捕获），度过 ACE 引擎
+    # 的可见性窗口；超过此年龄仍读不到则判定为真删除/异常，入队标 dead 待人工。
+    # 设为 0 可关闭延迟重试（退化为旧的"立即判死"语义，但不再降级 Delete）。
+    capture_defer_seconds: int = 120
+```
+
+- **默认值 120 秒**：覆盖本次事件观察到的 ~11 秒可见性窗口，并留足 10 倍余量；对 `poll_interval=10s` 意味着最多重试约 12 轮。
+- 单一配置项，`config.yaml` 无需改动即可生效（用默认值）。`defer_dead_op` 不暴露为配置（实现细节，固定为 `dead` 状态，见下）。
+
+---
+
+## 三、capture.py 改动（核心）
+
+### 3.1 CaptureStats 新增两个计数器
+
+```python
+@dataclass
+class CaptureStats:
+    # ... 既有字段 ...
+    read: int = 0
+    enqueued: int = 0
+    dedup_skipped: int = 0
+    downgraded: int = 0      # 保留字段，重构后恒为 0（兼容旧日志解析）
+    deferred: int = 0        # 【新】读不到行但年龄 < 阈值，跳过待下轮重试
+    aged_out: int = 0        # 【新】读不到行且年龄 ≥ 阈值，判死待人工
+    out_of_scope: int = 0
+    unknown_op: int = 0
+    # ... merge() / ops_str() 同步更新 ...
+```
+
+### 3.2 降级分支重构（`capture_file` 中 Insert/Update 回读逻辑）
+
+**替换** 现有的第 93-108 行（整段 `if op in ("Insert", "Update"):` 块）：
+
+```python
+if op in ("Insert", "Update"):
+    d = reader.read_row(lr.table_name, lr.record_id)
+    if d is None:
+        # 读不到行：不再降级 Delete。按 Access 日志年龄决定延迟重试还是判死。
+        # 必须计算日志年龄（原始设计无此逻辑）。
+        age_seconds = _log_age_seconds(lr.time)
+        if age_seconds < cfg.runtime.capture_defer_seconds:
+            # 暂态读不到（ACE 可见性窗口）：跳过，不入队、不清理。
+            # Access 日志因无对应 applied 队列行，cleanup 不会删除，下轮重试。
+            st.deferred += 1
+            log.warning(
+                "capture DEFER %s file=%s table=%s record_id=%s log_id=%s "
+                "log_time=%s age=%ds (source row unreadable; will retry next "
+                "cycle while log age < %ds)",
+                lr.operate_type, fm.file, lr.table_name, lr.record_id,
+                lr.id, lr.time, int(age_seconds),
+                cfg.runtime.capture_defer_seconds,
+            )
+            continue   # ← 关键：跳过本行，archive/queue 都不写
+        else:
+            # 超龄仍读不到：真删除或真异常。入队标 dead，不降级、不执行任何
+            # 破坏性操作。保留 Access 日志（无 applied 行 → cleanup 不删），
+            # 队列健康检查会告警，等待人工介入。
+            st.aged_out += 1
+            log.warning(
+                "capture AGED-OUT %s file=%s table=%s record_id=%s log_id=%s "
+                "log_time=%s age=%ds >= %ds -- enqueuing as dead for manual "
+                "review (source row still unreadable after defer window)",
+                lr.operate_type, fm.file, lr.table_name, lr.record_id,
+                lr.id, lr.time, int(age_seconds),
+                cfg.runtime.capture_defer_seconds,
+            )
+            op = "dead"  # 仅用于入队时的状态标记，见下
+    else:
+        row_data = json.dumps(d, ensure_ascii=False)
+```
+
+### 3.3 超龄行的入队方式（`aged_out` 分支）
+
+超龄行需要进 SyncQueue 但**不能被 apply 执行任何 SQL 操作**（没数据可插，也不能 Delete）。两种实现可选（我倾向 A）：
+
+**方案 A（推荐）：入队后直接标 dead，OperateType 保留原 Insert/Update 真相**
+- 入队时 `OperateType` 仍写 `Insert`/`Update`（保留原始意图，便于审计），`RowData=null`。
+- 入队后立即 `UPDATE ... SET Status='dead', ErrorMsg='source row unreadable after {age}s defer'`。
+- apply 的游标只选 `Status='pending'`，dead 行不会被处理 → 不会误删。
+- queue 健康检查已有 dead 告警（`service.py:166-184`），自动浮现。
+
+**方案 B：新增 OperateType='Noop'** — 改动面更大（apply 存储过程需识别），不推荐。
+
+> 需要在 `sql_writer.py` 新增一个方法 `insert_dead_row(row, error_msg)`，逻辑 = 先 `insert_queue_row`（去重插入）再 `UPDATE ... SET Status='dead', RetryCount=<对应>, ErrorMsg=?`。
+
+### 3.4 日志年龄计算辅助函数 `_log_age_seconds`
+
+```python
+import datetime as _dt
+
+def _log_age_seconds(log_time: object) -> float:
+    """Access 日志行 Time 字段距今的秒数。log_time 是 pyodbc 返回的 datetime。
+    异常时返回一个大数（视为已超龄），确保宁可判死也不无限重试。"""
+    try:
+        if isinstance(log_time, _dt.datetime):
+            return (_dt.datetime.now() - log_time).total_seconds()
+        # Access via ODBC 通常返回 datetime；兜底处理 naive/其它类型
+        return float("inf")
+    except Exception:
+        return float("inf")
+```
+
+> ⚠️ **时区/时钟注意**：`lr.time` 是 Access 端写入的本地时间，`datetime.now()` 也是本机本地时间，两者同在 114 主机同一时区，可直接相减。本次事件中 OriginalTime/CapturedAt 的"倒挂"现象（差11秒）不影响此逻辑——因为按年龄判断，即便 lr.time 偏早，age 只会被算得更大，倾向判死而非误伤，方向安全。
+
+---
+
+## 四、归档表（SyncLogArchive）的处理
+
+| 分支 | 是否写 archive | 理由 |
+|------|---------------|------|
+| DEFER（跳过） | **不写** | 日志保留在 Access，下轮 capture 会重新读到并正常归档；此时写 archive 反而会在去重表里留下"读不到"的半成品记录 |
+| AGED-OUT（判死） | **写** | 超龄是终态，需留永久审计（OriginalOperateType=Insert/Update, ProcessedOperateType='AgedOut', RowData=null, OriginalTime=lr.time） |
+
+> ProcessedOperateType 新增值 `'AgedOut'`（仅 archive 表用，varchar(10) 放得下 7 字符）。这是纯审计标记，不影响任何执行逻辑。
+
+---
+
+## 五、不改动的地方（明确边界）
+
+| 模块 | 是否改动 | 原因 |
+|------|---------|------|
+| `cleanup.py` | ❌ 不改 | 只删 `Status='applied'` 的日志；DEFER 行不入队无 applied 行 → 日志保留；AGED-OUT 标 dead 非 applied → 日志也保留。天然自洽。 |
+| `sql/02_sync_apply.sql` | ❌ 不改 | apply 游标只选 `pending`，dead 行天然跳过；DEFER 行根本不入队。 |
+| `sql/01_sync_queue.sql` | ❌ 不改 | 不新增列，不改索引。 |
+| `service.py` | ❌ 不改 | 队列健康检查已有 error/dead 告警（`queue_error_samples`），AGED-OUT 的 dead 行会自动被它捕获并 WARNING。capture summary 日志格式已包含新计数器（由 CaptureStats.ops_str/merge 驱动）。 |
+| `access_reader.py` | ❌ 不改 | `read_row` 行为不变。 |
+| `config.yaml` | ❌ 不改 | 用默认值 120s 即可。 |
+
+---
+
+## 六、本次事件 5 行的重放（重构后）
+
+```
+cycle N (09:00:50): capture 读到 5 条 Insert 日志
+  → read_row 返回 None
+  → age = now(09:00:50) - log_time(09:01:01) → 注: 因 Access 时间戳特性 age 可能算成负或小
+  → 即便按最保守计算，age 远 < 120s
+  → DEFER：跳过不入队，写 WARNING，Access 日志保留
+
+cycle N+1 (09:01:00): capture 再次读到这 5 条日志
+  → read_row 此刻可见性窗口已过（11s > 窗口）→ 读到行 ✅
+  → 正常入队 OperateType=Insert，带完整 RowData
+  → apply MERGE → SQL 正确写入 5 行 ✅
+  → cleanup 删 Access 日志（这次是 applied，合理）
+```
+
+**结果：8/4 compare 不再出现 missing_in_sql=5。**
+
+---
+
+## 七、验证计划
+
+1. **单元测试**（`tests/test_capture.py`）：
+   - mock `read_row` 返回 None + `lr.time` 为近时 → 断言 `deferred=1, enqueued=0, aged_out=0`，不调用 `insert_queue_row` / `insert_archive_row`。
+   - mock `read_row` 返回 None + `lr.time` 为 200s 前 → 断言 `aged_out=1`，调用 `insert_dead_row`，Status=dead。
+   - mock `read_row` 返回 dict + 任意时间 → 断言正常入队（回归测试）。
+   - `capture_defer_seconds=0` → 任何读不到都立即判死（边界）。
+2. **现有测试回归**：`pytest` 全绿（确保去重/正常 Insert/真 Delete 路径不受影响）。
+3. **集成验证**（部署后观察 1-2 天）：
+   - 关注 capture summary 日志的 `deferred=` 计数，确认批量插入场景下有 defer 发生且下轮 enqueued。
+   - 关注 `queue health` WARNING，确认 dead 行（如有）被正确告警。
+   - 跑 `compare --granularity ids`，确认无 missing_in_sql。
+
+---
+
+## 八、改动文件清单
+
+| 文件 | 改动类型 | 说明 |
+|------|---------|------|
+| `src/sync/config.py` | 新增字段 | RuntimeConfig 加 `capture_defer_seconds: int = 120` |
+| `src/sync/capture.py` | 核心重构 | 降级分支 → defer/aged_out 分支；CaptureStats 加 2 计数器；新增 `_log_age_seconds` |
+| `src/sync/sql_writer.py` | 新增方法 | `insert_dead_row(row, error_msg)`：去重插入后立即标 dead |
+| `tests/test_capture.py` | 新增用例 | 覆盖 DEFER / AGED-OUT / 正常 / 边界 4 种情况 |
+
+**总计 4 个文件，零 SQL/零 schema 改动。**
+
+---
+
+## 九、待你确认的决策点
+
+1. **`capture_defer_seconds` 默认值 120s** 是否合适？（覆盖11s窗口×10倍余量）
+2. **AGED-OUT 行的处理**：入队标 dead（方案A，推荐）vs 其它？
+3. **archive 表 ProcessedOperateType 新增值 `'AgedOut'`** 是否可接受？
+4. **downgraded 计数器**：保留为恒0（向后兼容旧日志解析）还是直接删除？
+
+确认后我即按此方案执行。

main.py

@@ -17,6 +17,7 @@ was launched or whether the venv already has ``src`` on its path.
 from __future__ import annotations
 
 import argparse
+import logging
 import os
 import sys
 
@@ -27,9 +28,10 @@ from sync.config import load_config
 from sync.logging_setup import setup_logging
 from sync.fullsync import full_sync
 from sync import service
-from sync.compare import compare, any_mismatch, format_report
+from sync.compare import compare, any_mismatch, format_report, write_report
 
 CONFIG_PATH = os.path.join(os.path.dirname(os.path.abspath(__file__)), "config.yaml")
+log = logging.getLogger("main")
 
 
 def _parse_args(argv):
@@ -99,11 +101,14 @@ def main(argv=None) -> int:
     if args.command == "compare":
         results = compare(cfg, granularity=args.granularity,
                           db_filter=args.db, table_filter=args.table)
-        report = format_report(results, args.granularity)
-        print(report)
-        if args.report:
-            with open(args.report, "w", encoding="utf-8") as f:
-                f.write(report + "\n")
+        # Persist the report as a dated log file under the logging directory
+        # (logs/ by default); --report still allows an extra custom path.
+        log_dir = os.path.dirname((cfg.logging or {}).get("path", "sync.log")) or "."
+        written = write_report(results, args.granularity, log_dir=log_dir,
+                               extra_path=args.report)
+        print(format_report(results, args.granularity))
+        log.info("compare finished (granularity=%s) report=%s mismatch=%s",
+                 args.granularity, written, any_mismatch(results))
         return 1 if any_mismatch(results) else 0
 
     return 2  # unreachable: argparse requires a subcommand

run_compare_ids.cmd

@@ -0,0 +1,3 @@
+@echo off
+cd /d C:\Users\peng\Projects\ProductionDataBaseSync_DataMacro
+.venv\Scripts\python.exe main.py compare --granularity ids >> logs\compare_task_stdout.log 2>&1

sql/00_schema.sql

@@ -0,0 +1,12 @@
+-- ProductionDataBaseSync: dedicated schema that groups every object owned by
+-- the Access -> SQL Server sync (SyncQueue staging, SyncLogArchive audit store,
+-- and the usp_SyncApply procedure). Keeping them out of dbo makes ownership and
+-- housekeeping explicit.
+-- Idempotent: CREATE SCHEMA must be the only statement in its batch, so it is
+-- wrapped in EXEC() behind an existence check.
+
+IF NOT EXISTS (SELECT 1 FROM sys.schemas WHERE name = 'ProductionDataBaseSync')
+BEGIN
+    EXEC('CREATE SCHEMA ProductionDataBaseSync');
+END
+GO

sql/01_sync_queue.sql

@@ -1,9 +1,10 @@
 -- SyncQueue: staging table for the Access -> SQL Server one-way sync.
+-- Lives under the ProductionDataBaseSync schema (run 00_schema.sql first).
 -- Idempotent: safe to re-run (table created only if absent; indexes only if absent).
 
-IF OBJECT_ID('dbo.SyncQueue', 'U') IS NULL
+IF OBJECT_ID('ProductionDataBaseSync.SyncQueue', 'U') IS NULL
 BEGIN
-    CREATE TABLE dbo.SyncQueue (
+    CREATE TABLE ProductionDataBaseSync.SyncQueue (
         QueueID      bigint IDENTITY(1,1) NOT NULL,
         SourceFile   nvarchar(255)        NOT NULL,
         SourceTable  nvarchar(255)        NOT NULL,
@@ -18,6 +19,7 @@ BEGIN
         ErrorMsg     nvarchar(max)        NULL,
         CapturedAt   datetime2            NOT NULL CONSTRAINT DF_SyncQueue_Captured DEFAULT sysdatetime(),
         AppliedAt    datetime2            NULL,
+        CleanedAt    datetime2            NULL,
         CONSTRAINT PK_SyncQueue PRIMARY KEY CLUSTERED (QueueID)
     );
 END
@@ -25,38 +27,27 @@ GO
 
 IF NOT EXISTS (SELECT 1 FROM sys.indexes
                WHERE name = 'UX_SyncQueue_Dedup'
-                 AND object_id = OBJECT_ID('dbo.SyncQueue'))
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncQueue'))
 BEGIN
     CREATE UNIQUE INDEX UX_SyncQueue_Dedup
-        ON dbo.SyncQueue(SourceFile, SourceTable, SourceLogID);
+        ON ProductionDataBaseSync.SyncQueue(SourceFile, SourceTable, SourceLogID);
 END
 GO
 
 IF NOT EXISTS (SELECT 1 FROM sys.indexes
                WHERE name = 'IX_SyncQueue_Pending'
-                 AND object_id = OBJECT_ID('dbo.SyncQueue'))
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncQueue'))
 BEGIN
     CREATE INDEX IX_SyncQueue_Pending
-        ON dbo.SyncQueue(Status, TargetSchema, TargetTable);
-END
-GO
-
--- Cleanup bookkeeping: track when a queue row's Access log counterpart has
--- been physically deleted, so cleanup never re-deletes the same IDs and the
--- table can be purged to bound its growth.
-IF NOT EXISTS (SELECT 1 FROM sys.columns
-               WHERE object_id = OBJECT_ID('dbo.SyncQueue')
-                 AND name = 'CleanedAt')
-BEGIN
-    ALTER TABLE dbo.SyncQueue ADD CleanedAt datetime2 NULL;
+        ON ProductionDataBaseSync.SyncQueue(Status, TargetSchema, TargetTable);
 END
 GO
 
 IF NOT EXISTS (SELECT 1 FROM sys.indexes
                WHERE name = 'IX_SyncQueue_Cleaned'
-                 AND object_id = OBJECT_ID('dbo.SyncQueue'))
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncQueue'))
 BEGIN
     CREATE INDEX IX_SyncQueue_Cleaned
-        ON dbo.SyncQueue(Status, CleanedAt);
+        ON ProductionDataBaseSync.SyncQueue(Status, CleanedAt);
 END
 GO

sql/02_sync_apply.sql

@@ -10,24 +10,42 @@
 -- Delete), which let a stale Delete outrank a newer Insert for the same RecordID
 -- and silently drop a row whose true last op was an Insert. Routing off the one
 -- winning row's OperateType guarantees only the genuine last op wins.
+--
+-- AUDIT NOTE: when ProductionDataBaseSync.SyncApplyRunLog exists (see
+-- sql/04_sync_apply_runlog.sql), one audit row is written per target table and
+-- per invocation: pending/distinct counts going in, the MERGE/DELETE rowcounts,
+-- how many queue rows were flipped to applied (or to error/dead on failure),
+-- the error message, the duration, and the caller-supplied @CycleID that ties
+-- the row to the Python service log's [cyc:...] lines. The audit insert is
+-- best-effort (wrapped in its own TRY/CATCH, outside the data transaction) and
+-- can never fail the apply itself. @CycleID defaults to NULL so the legacy
+-- single-parameter EXEC keeps working.
 
-CREATE OR ALTER PROCEDURE dbo.usp_SyncApply
-    @MaxRetries INT = 5
+CREATE OR ALTER PROCEDURE ProductionDataBaseSync.usp_SyncApply
+    @MaxRetries INT = 5,
+    @CycleID    NVARCHAR(40) = NULL
 AS
 BEGIN
     SET NOCOUNT ON;
 
     DECLARE @sch NVARCHAR(128), @tbl NVARCHAR(255), @FullName NVARCHAR(514);
     DECLARE @sql NVARCHAR(MAX), @cols NVARCHAR(MAX), @upd NVARCHAR(MAX), @ins NVARCHAR(MAX);
+    DECLARE @hasRunLog bit =
+        CASE WHEN OBJECT_ID('ProductionDataBaseSync.SyncApplyRunLog', 'U') IS NOT NULL
+             THEN 1 ELSE 0 END;
+    DECLARE @t0 DATETIME2, @pending INT, @distinctRecs INT,
+            @merged INT, @deleted INT, @applied INT,
+            @errCnt INT, @deadCnt INT,
+            @errMsg NVARCHAR(MAX), @outcome VARCHAR(10);
 
     -- Re-queue rows still under the retry budget.
-    UPDATE dbo.SyncQueue
+    UPDATE ProductionDataBaseSync.SyncQueue
        SET Status = 'pending'
      WHERE Status = 'error' AND RetryCount < @MaxRetries;
 
     DECLARE cur CURSOR LOCAL FAST_FORWARD FOR
         SELECT DISTINCT TargetSchema, TargetTable
-          FROM dbo.SyncQueue
+          FROM ProductionDataBaseSync.SyncQueue
          WHERE Status = 'pending';
 
     OPEN cur;
@@ -37,6 +55,19 @@ BEGIN
     BEGIN
         SET @FullName = QUOTENAME(@sch) + N'.' + QUOTENAME(@tbl);
 
+        -- Per-table audit state. Explicit reset every iteration: local
+        -- variables keep their previous value across cursor loops.
+        SELECT @t0 = SYSDATETIME(),
+               @merged = NULL, @deleted = NULL, @applied = NULL,
+               @errCnt = NULL, @deadCnt = NULL,
+               @errMsg = NULL, @outcome = 'ok',
+               @cols = NULL, @upd = NULL, @ins = NULL;
+
+        SELECT @pending      = COUNT(*),
+               @distinctRecs = COUNT(DISTINCT RecordID)
+          FROM ProductionDataBaseSync.SyncQueue
+         WHERE TargetSchema = @sch AND TargetTable = @tbl AND Status = 'pending';
+
         BEGIN TRY
             BEGIN TRAN;
             -- @cols: comma-quoted column names (for INSERT target list)
@@ -66,11 +97,14 @@ BEGIN
                 -- pending ops so the rn=1 row is the true last op for that
                 -- RecordID; an earlier Delete can no longer outrank a newer
                 -- Insert for the same RecordID.
+                -- AUDIT: @@ROWCOUNT is captured into @MergedOut IMMEDIATELY
+                -- after the MERGE -- SET IDENTITY_INSERT (like any SET option)
+                -- resets @@ROWCOUNT, so the order below is load-bearing.
                 SET @sql = N'SET IDENTITY_INSERT ' + @FullName + N' ON;'
                          + N';WITH ranked AS ('
                          + N'  SELECT RecordID, OperateType, RowData,'
                          + N'         ROW_NUMBER() OVER (PARTITION BY RecordID ORDER BY SourceLogID DESC) rn'
-                         + N'    FROM dbo.SyncQueue'
+                         + N'    FROM ProductionDataBaseSync.SyncQueue'
                          + N'   WHERE TargetSchema=@sch AND TargetTable=@tbl AND Status=''pending'''
                          + N')'
                          + N'MERGE ' + @FullName + N' WITH (HOLDLOCK) AS tgt'
@@ -81,28 +115,33 @@ BEGIN
                          + N' WHEN MATCHED THEN UPDATE SET ' + @upd
                          + N' WHEN NOT MATCHED THEN INSERT (ID,' + @cols + N')'
                          + N'  VALUES (TRY_CAST(src.RecordID AS int),' + @ins + N');'
+                         + N'SET @MergedOut = @@ROWCOUNT;'
                          + N'SET IDENTITY_INSERT ' + @FullName + N' OFF;';
                 EXEC sp_executesql @sql,
-                     N'@sch NVARCHAR(128),@tbl NVARCHAR(255)', @sch, @tbl;
+                     N'@sch NVARCHAR(128),@tbl NVARCHAR(255),@MergedOut INT OUTPUT',
+                     @sch, @tbl, @MergedOut = @merged OUTPUT;
 
                 -- Delete: winners (rn=1) whose winning OperateType is Delete.
                 -- Same ranked CTE — only the genuine last op can be a delete.
                 SET @sql = N';WITH ranked AS ('
                          + N'  SELECT RecordID, OperateType,'
                          + N'         ROW_NUMBER() OVER (PARTITION BY RecordID ORDER BY SourceLogID DESC) rn'
-                         + N'    FROM dbo.SyncQueue'
+                         + N'    FROM ProductionDataBaseSync.SyncQueue'
                          + N'   WHERE TargetSchema=@sch AND TargetTable=@tbl AND Status=''pending'''
                          + N')'
                          + N'DELETE t FROM ' + @FullName + N' t'
                          + N' JOIN (SELECT RecordID FROM ranked WHERE rn=1 AND OperateType=''Delete'') d'
-                         + N'   ON t.ID = TRY_CAST(d.RecordID AS int);';
+                         + N'   ON t.ID = TRY_CAST(d.RecordID AS int);'
+                         + N'SET @DeletedOut = @@ROWCOUNT;';
                 EXEC sp_executesql @sql,
-                     N'@sch NVARCHAR(128),@tbl NVARCHAR(255)', @sch, @tbl;
+                     N'@sch NVARCHAR(128),@tbl NVARCHAR(255),@DeletedOut INT OUTPUT',
+                     @sch, @tbl, @DeletedOut = @deleted OUTPUT;
             END
 
-            UPDATE dbo.SyncQueue
+            UPDATE ProductionDataBaseSync.SyncQueue
                SET Status = 'applied', AppliedAt = SYSDATETIME()
              WHERE TargetSchema = @sch AND TargetTable = @tbl AND Status = 'pending';
+            SET @applied = @@ROWCOUNT;
 
             COMMIT;
         END TRY
@@ -113,13 +152,48 @@ BEGIN
             -- issues its own rollback. We roll back here so the partial per-table
             -- work is discarded before marking rows as 'error'/'dead'.
             IF @@TRANCOUNT > 0 ROLLBACK;
-            UPDATE dbo.SyncQueue
-               SET Status      = CASE WHEN RetryCount + 1 >= @MaxRetries THEN 'dead' ELSE 'error' END,
-                   RetryCount   = RetryCount + 1,
-                   ErrorMsg     = ERROR_MESSAGE()
+            SELECT @errMsg = ERROR_MESSAGE(), @outcome = 'error';
+
+            -- Split of the previous single CASE update so the audit row can
+            -- report exactly how many rows died vs. how many will be retried.
+            -- Net effect on SyncQueue is identical.
+            UPDATE ProductionDataBaseSync.SyncQueue
+               SET Status = 'dead', RetryCount = RetryCount + 1, ErrorMsg = @errMsg
+             WHERE TargetSchema = @sch AND TargetTable = @tbl AND Status = 'pending'
+               AND RetryCount + 1 >= @MaxRetries;
+            SET @deadCnt = @@ROWCOUNT;
+
+            UPDATE ProductionDataBaseSync.SyncQueue
+               SET Status = 'error', RetryCount = RetryCount + 1, ErrorMsg = @errMsg
              WHERE TargetSchema = @sch AND TargetTable = @tbl AND Status = 'pending';
+            SET @errCnt = @@ROWCOUNT;
         END CATCH
 
+        -- Best-effort audit row: sits outside the data transaction (after
+        -- COMMIT/ROLLBACK) so it survives either outcome, and its own failure
+        -- can never break the apply loop.
+        IF @hasRunLog = 1
+        BEGIN
+            BEGIN TRY
+                INSERT ProductionDataBaseSync.SyncApplyRunLog
+                    (CycleID, TargetSchema, TargetTable,
+                     PendingCount, DistinctRecords,
+                     MergedCount, DeletedCount, AppliedCount,
+                     ErrorCount, DeadCount,
+                     Outcome, ErrorMsg, StartedAt, DurationMs)
+                VALUES
+                    (@CycleID, @sch, @tbl,
+                     @pending, @distinctRecs,
+                     @merged, @deleted, @applied,
+                     @errCnt, @deadCnt,
+                     @outcome, @errMsg, @t0,
+                     DATEDIFF(millisecond, @t0, SYSDATETIME()));
+            END TRY
+            BEGIN CATCH
+                PRINT 'SyncApplyRunLog insert failed: ' + ERROR_MESSAGE();
+            END CATCH
+        END
+
         FETCH NEXT FROM cur INTO @sch, @tbl;
     END
 

sql/03_sync_log_archive.sql

@@ -0,0 +1,71 @@
+-- SyncLogArchive: permanent, append-only audit store for every Access change-log
+-- row consumed by the incremental sync. This is the durable evidence layer that
+-- SyncQueue is NOT: SyncQueue is a transient work queue (purged 24h after a row
+-- is cleaned) and it only stores the *processed* OperateType, so a downgrade
+-- (e.g. capture turning an Insert into a Delete when the row is momentarily
+-- unreadable) erases the original intent. This table preserves both the ORIGINAL
+-- operate type recorded by the Access data macro and the PROCESSED type actually
+-- sent to SQL Server, plus the original Access log timestamp and the row payload.
+--
+-- With this in place, cases like the 14287 incident (a real Insert applied to SQL
+-- as a Delete) stay fully reconstructible: OriginalOperateType != ProcessedOperateType
+-- flags exactly where the pipeline diverged from the source.
+--
+-- Retention: PERMANENT. No purge job touches this table. SyncQueue keeps its
+-- short-lived queue role; this table keeps history. Lives under the
+-- ProductionDataBaseSync schema (run 00_schema.sql first).
+-- Idempotent: safe to re-run.
+
+IF OBJECT_ID('ProductionDataBaseSync.SyncLogArchive', 'U') IS NULL
+BEGIN
+    CREATE TABLE ProductionDataBaseSync.SyncLogArchive (
+        ArchiveID            bigint IDENTITY(1,1) NOT NULL,
+        SourceFile           nvarchar(255)        NOT NULL,
+        SourceTable          nvarchar(255)        NOT NULL,
+        SourceLogID          bigint               NOT NULL,
+        RecordID             nvarchar(50)         NOT NULL,
+        TargetSchema         nvarchar(128)        NOT NULL,
+        TargetTable          nvarchar(255)        NOT NULL,
+        OriginalOperateType  varchar(10)          NOT NULL,   -- as recorded by the Access data macro
+        ProcessedOperateType varchar(10)          NOT NULL,   -- as actually sent to SyncQueue / SQL
+        RowData              nvarchar(max)         NULL,       -- captured row payload (NULL for Delete)
+        OriginalTime         datetime2             NULL,       -- Access TableChangeLog.Time (previously discarded)
+        CapturedAt           datetime2             NOT NULL
+                             CONSTRAINT DF_SyncLogArchive_Captured DEFAULT sysdatetime(),
+        CONSTRAINT PK_SyncLogArchive PRIMARY KEY CLUSTERED (ArchiveID)
+    );
+END
+GO
+
+-- Dedup: one archive row per source log entry. Capture may re-run the same log
+-- row if a prior cycle's apply failed (the Access log is only deleted after a
+-- successful apply), so the write path uses IF NOT EXISTS on these keys.
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'UX_SyncLogArchive_Dedup'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncLogArchive'))
+BEGIN
+    CREATE UNIQUE INDEX UX_SyncLogArchive_Dedup
+        ON ProductionDataBaseSync.SyncLogArchive(SourceFile, SourceTable, SourceLogID);
+END
+GO
+
+-- Evidence lookup by table + record (e.g. "show every log ever seen for ID 14287").
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'IX_SyncLogArchive_Record'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncLogArchive'))
+BEGIN
+    CREATE INDEX IX_SyncLogArchive_Record
+        ON ProductionDataBaseSync.SyncLogArchive(SourceTable, RecordID);
+END
+GO
+
+-- Fast filter for the anomaly the archive exists to catch: original != processed.
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'IX_SyncLogArchive_Divergence'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncLogArchive'))
+BEGIN
+    CREATE INDEX IX_SyncLogArchive_Divergence
+        ON ProductionDataBaseSync.SyncLogArchive(OriginalOperateType, ProcessedOperateType)
+        INCLUDE (SourceFile, SourceTable, RecordID, CapturedAt);
+END
+GO

sql/04_sync_apply_runlog.sql

@@ -0,0 +1,75 @@
+-- SyncApplyRunLog: per-invocation, per-target-table audit of what usp_SyncApply
+-- actually did. This closes the biggest observability gap in the pipeline: the
+-- apply phase used to be a black box ("apply done") -- queue rows could flip
+-- to 'error' or 'dead' with no trace in the service log, and there was no
+-- record of how many rows a MERGE/DELETE touched at any point in time. With
+-- this table, "what did apply do to table X around time T, and did it fail?"
+-- is a single indexed query, and CycleID joins each row back to the exact
+-- [cyc:xxxxxxxx] lines in the Python service log.
+--
+-- Written by usp_SyncApply (sql/02_sync_apply.sql) as a best-effort insert per
+-- (invocation, target table). Idle cycles write nothing (the proc's cursor
+-- only visits tables that have pending rows), so growth tracks real change
+-- traffic, not poll frequency. Retention: unmanaged by default; if it ever
+-- grows large, purge by StartedAt, e.g.
+--   DELETE FROM ProductionDataBaseSync.SyncApplyRunLog
+--    WHERE StartedAt < DATEADD(day, -90, SYSDATETIME());
+--
+-- Lives under the ProductionDataBaseSync schema (run 00_schema.sql first).
+-- Idempotent: safe to re-run. Deploy alongside the updated 02_sync_apply.sql;
+-- ordering is forgiving either way (the proc checks for this table and skips
+-- the audit insert when it is absent).
+
+IF OBJECT_ID('ProductionDataBaseSync.SyncApplyRunLog', 'U') IS NULL
+BEGIN
+    CREATE TABLE ProductionDataBaseSync.SyncApplyRunLog (
+        RunLogID        bigint IDENTITY(1,1) NOT NULL,
+        CycleID         nvarchar(40)   NULL,      -- correlation id from the Python service ([cyc:...])
+        TargetSchema    nvarchar(128)  NOT NULL,
+        TargetTable     nvarchar(255)  NOT NULL,
+        PendingCount    int            NOT NULL,  -- pending queue rows seen for this table
+        DistinctRecords int            NULL,      -- distinct RecordIDs among them
+        MergedCount     int            NULL,      -- rows affected by the MERGE (insert + update)
+        DeletedCount    int            NULL,      -- rows affected by the DELETE
+        AppliedCount    int            NULL,      -- queue rows flipped to 'applied'
+        ErrorCount      int            NULL,      -- queue rows flipped to 'error' (will retry)
+        DeadCount       int            NULL,      -- queue rows flipped to 'dead' (retries exhausted)
+        Outcome         varchar(10)    NOT NULL,  -- 'ok' | 'error'
+        ErrorMsg        nvarchar(max)  NULL,
+        StartedAt       datetime2      NOT NULL
+                        CONSTRAINT DF_SyncApplyRunLog_Started DEFAULT sysdatetime(),
+        DurationMs      int            NULL,
+        CONSTRAINT PK_SyncApplyRunLog PRIMARY KEY CLUSTERED (RunLogID)
+    );
+END
+GO
+
+-- Join back to the Python service log of one cycle.
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'IX_SyncApplyRunLog_Cycle'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncApplyRunLog'))
+BEGIN
+    CREATE INDEX IX_SyncApplyRunLog_Cycle
+        ON ProductionDataBaseSync.SyncApplyRunLog(CycleID);
+END
+GO
+
+-- "What happened to this table around time T?"
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'IX_SyncApplyRunLog_Table'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncApplyRunLog'))
+BEGIN
+    CREATE INDEX IX_SyncApplyRunLog_Table
+        ON ProductionDataBaseSync.SyncApplyRunLog(TargetSchema, TargetTable, StartedAt);
+END
+GO
+
+-- Fast scan for failed applies.
+IF NOT EXISTS (SELECT 1 FROM sys.indexes
+               WHERE name = 'IX_SyncApplyRunLog_Outcome'
+                 AND object_id = OBJECT_ID('ProductionDataBaseSync.SyncApplyRunLog'))
+BEGIN
+    CREATE INDEX IX_SyncApplyRunLog_Outcome
+        ON ProductionDataBaseSync.SyncApplyRunLog(Outcome, StartedAt);
+END
+GO

src/sync/access_reader.py

@@ -94,7 +94,9 @@ class AccessReader:
         ``cursor.rowcount``), so the caller can report honest counts. A no-op
         (returns 0) when ``ids`` is empty. Retries with linear backoff because
         the live client may briefly hold a page lock on ``TableChangeLog``.
-        Raises on final lock failure.
+        Each retry is logged at WARNING (previously a silent sleep) and the
+        final lock failure at ERROR before raising, so lock churn on the
+        production files is visible in the audit trail.
         """
         if not ids:
             return 0
@@ -121,8 +123,20 @@ class AccessReader:
                     msg = str(e)
                     is_lock = "被锁定" in msg or "-1102" in msg
                     if is_lock and attempt < retries - 1:
+                        log.warning(
+                            "TableChangeLog delete lock contention "
+                            "(attempt %d/%d) db=%s ids=%s..%s -- retrying: %s",
+                            attempt + 1, retries, self.db_path,
+                            chunk[0], chunk[-1], msg[:200],
+                        )
                         time.sleep(0.2 * (attempt + 1))
                     else:
+                        if is_lock:
+                            log.error(
+                                "TableChangeLog delete still locked after %d "
+                                "attempts db=%s ids=%s..%s -- giving up",
+                                retries, self.db_path, chunk[0], chunk[-1],
+                            )
                         raise
         return total
 

src/sync/capture.py

@@ -1,39 +1,250 @@
+"""Capture phase: read Access change-log rows and stage them into SyncQueue.
+
+Every consumed ``TableChangeLog`` row is appended to the permanent audit store
+(``SyncLogArchive``) BEFORE it is enqueued, so the original evidence survives
+cleanup. On top of that, this module emits a detailed audit trail to the
+service log:
+
+- WARNING for every Insert/Update that could not be read back from the source
+  table at capture time. Two outcomes, both logged by identity (record id,
+  log id, log time, age):
+    * DEFER  -- the log row is younger than ``capture_defer_seconds``: treated
+      as an ACE visibility-latency window. The row is NOT enqueued, the Access
+      log is left intact (cleanup only deletes rows whose queue status is
+      ``applied``), and the next cycle re-reads it. This is the fix for the
+      data-loss incident where an Insert downgraded to Delete silently dropped
+      rows from SQL Server (see docs/plan-capture-defer-by-age.md).
+    * AGED-OUT -- still unreadable past the defer window: enqueued directly as
+      ``dead`` (usp_SyncApply never selects dead rows, so no destructive SQL
+      runs) and left for manual review; the Access log is also preserved.
+- WARNING for unknown operate types, with enough identity (log id / record id
+  / time) to locate and repair the offending log row manually;
+- a per-file INFO summary: rows read, newly enqueued, dedup-skipped
+  (re-capture after a failed apply -- a symptom worth noticing), deferred,
+  aged-out, out-of-scope, unknown ops, the processed log-ID range and a
+  per-operation breakdown;
+- DEBUG detail for individual out-of-scope and dedup skips.
+"""
 from __future__ import annotations
-import json, logging
+
+import datetime as _dt
+import json
+import logging
+from dataclasses import dataclass, field
+
 from .access_reader import AccessReader
-from .sql_writer import SqlWriter, QueueRow
+from .sql_writer import SqlWriter, QueueRow, ArchiveRow
 from .config import FileMapping, SyncConfig
 from .targets import is_synced_table
 
 log = logging.getLogger(__name__)
 
-def capture_file(fm: FileMapping, reader: AccessReader, writer: SqlWriter, cfg: SyncConfig) -> int:
+
+def _log_age_seconds(log_time: object) -> float:
+    """Seconds elapsed since the Access log row's ``Time`` value.
+
+    ``log_time`` is the raw pyodbc datetime from ``TableChangeLog.Time`` (set
+    by the Access data macro). Both it and ``datetime.now()`` run on the same
+    host/clock, so direct subtraction is valid. On any anomaly (missing /
+    non-datetime value) returns ``inf`` so the caller errs toward ageing out
+    rather than retrying forever.
+    """
+    try:
+        if isinstance(log_time, _dt.datetime):
+            return (_dt.datetime.now() - log_time).total_seconds()
+        return float("inf")
+    except Exception:
+        return float("inf")
+
+
+@dataclass
+class CaptureStats:
+    """Counters for one capture pass (per file, or aggregated per cycle)."""
+
+    read: int = 0            # change-log rows read from Access
+    enqueued: int = 0        # rows newly inserted into SyncQueue
+    dedup_skipped: int = 0   # already queued (re-capture after a failed apply)
+    deferred: int = 0        # Insert/Update unreadable but young -> retry next cycle
+    aged_out: int = 0        # Insert/Update still unreadable past defer window -> dead
+    out_of_scope: int = 0    # log rows for tables outside the sync scope
+    unknown_op: int = 0      # log rows with an unrecognised OperateType
+    min_log_id: int | None = None
+    max_log_id: int | None = None
+    ops: dict[str, int] = field(default_factory=dict)  # processed op -> count
+
+    def note_op(self, op: str) -> None:
+        self.ops[op] = self.ops.get(op, 0) + 1
+
+    def merge(self, other: "CaptureStats") -> None:
+        """Fold *other* into this instance (cycle-level aggregation)."""
+        self.read += other.read
+        self.enqueued += other.enqueued
+        self.dedup_skipped += other.dedup_skipped
+        self.deferred += other.deferred
+        self.aged_out += other.aged_out
+        self.out_of_scope += other.out_of_scope
+        self.unknown_op += other.unknown_op
+        for k, v in other.ops.items():
+            self.ops[k] = self.ops.get(k, 0) + v
+        for attr, pick in (("min_log_id", min), ("max_log_id", max)):
+            a, b = getattr(self, attr), getattr(other, attr)
+            if a is None:
+                setattr(self, attr, b)
+            elif b is not None:
+                setattr(self, attr, pick(a, b))
+
+    def ops_str(self) -> str:
+        return ",".join(f"{k}={v}" for k, v in sorted(self.ops.items())) or "-"
+
+
+def capture_file(fm: FileMapping, reader: AccessReader, writer: SqlWriter,
+                 cfg: SyncConfig) -> CaptureStats:
+    """Capture one file's pending change-log rows. Returns detailed stats.
+
+    NOTE: previously returned a bare int (rows enqueued); that count is now
+    ``stats.enqueued``. ``sync.service.cycle`` is the only in-repo caller and
+    has been updated accordingly.
+    """
     rows = reader.read_log(cfg.runtime.capture_batch_size)
-    n = 0
+    st = CaptureStats(read=len(rows))
+    if rows:  # read_log orders by ID ascending
+        st.min_log_id, st.max_log_id = rows[0].id, rows[-1].id
+
     for lr in rows:
         if not is_synced_table(fm, lr.table_name):
+            st.out_of_scope += 1
+            log.debug("capture skip (out of scope) file=%s table=%s log_id=%s",
+                      fm.file, lr.table_name, lr.id)
             continue
         op = lr.operate_type
         row_data = None
         if op in ("Insert", "Update"):
             d = reader.read_row(lr.table_name, lr.record_id)
             if d is None:
-                op = "Delete"  # 行已删，降级
+                # 回读不到整行：不再降级 Delete。按 Access 日志年龄决定动作，
+                # 根治"Insert 降级 Delete 致数据丢失"缺陷。
+                age = _log_age_seconds(lr.time)
+                if age < cfg.runtime.capture_defer_seconds:
+                    # 暂态（ACE 可见性延迟）：跳过，不入队、不写 archive。
+                    # Access 日志因无 applied 队列行，cleanup 不会删除，
+                    # 下一轮 cycle 会重新读到。
+                    st.deferred += 1
+                    log.warning(
+                        "capture DEFER %s file=%s table=%s record_id=%s "
+                        "log_id=%s log_time=%s age=%ds (source row unreadable; "
+                        "will retry next cycle while age < %ds)",
+                        lr.operate_type, fm.file, lr.table_name, lr.record_id,
+                        lr.id, lr.time, int(age),
+                        cfg.runtime.capture_defer_seconds,
+                    )
+                    continue
+                # 超龄仍读不到：真删除或真异常。入队标 dead，不降级、不执行
+                # 任何破坏性 SQL。保留 Access 日志（无 applied 行 → cleanup
+                # 不删），队列健康检查会告警，等待人工介入。
+                st.aged_out += 1
+                log.warning(
+                    "capture AGED-OUT %s file=%s table=%s record_id=%s "
+                    "log_id=%s log_time=%s age=%ds >= %ds -- enqueuing as "
+                    "dead for manual review (source row still unreadable "
+                    "after defer window)",
+                    lr.operate_type, fm.file, lr.table_name, lr.record_id,
+                    lr.id, lr.time, int(age),
+                    cfg.runtime.capture_defer_seconds,
+                )
+                target_schema = fm.schema
+                target_table = fm.target_table(lr.table_name)
+                writer.insert_archive_row(ArchiveRow(
+                    source_file=fm.file,
+                    source_table=lr.table_name,
+                    source_log_id=lr.id,
+                    record_id=lr.record_id,
+                    target_schema=target_schema,
+                    target_table=target_table,
+                    original_operate_type=lr.operate_type,
+                    processed_operate_type="AgedOut",
+                    row_data=None,
+                    original_time=lr.time,
+                ))
+                qr = QueueRow(
+                    source_file=fm.file,
+                    source_table=lr.table_name,
+                    record_id=lr.record_id,
+                    target_schema=target_schema,
+                    target_table=target_table,
+                    source_log_id=lr.id,
+                    operate_type=op,   # 保留原始 Insert/Update，便于审计
+                    row_data=None,
+                )
+                writer.insert_dead_row(
+                    qr,
+                    f"source row unreadable after {int(age)}s defer window "
+                    f"(capture_defer_seconds={cfg.runtime.capture_defer_seconds})",
+                )
+                continue
             else:
                 row_data = json.dumps(d, ensure_ascii=False)
         elif op != "Delete":
-            log.warning("unknown OperateType %r in %s log %s", op, fm.file, lr.id)
+            st.unknown_op += 1
+            log.warning(
+                "capture UNKNOWN OperateType %r file=%s table=%s "
+                "record_id=%s log_id=%s log_time=%s -- row skipped; it will "
+                "be re-read every cycle until removed from TableChangeLog",
+                op, fm.file, lr.table_name, lr.record_id, lr.id, lr.time,
+            )
             continue
+        target_schema = fm.schema
+        target_table = fm.target_table(lr.table_name)
+        # Persist the ORIGINAL log entry to the permanent audit store BEFORE the
+        # queue insert (and long before cleanup deletes the Access log). This
+        # keeps both the source operate type (lr.operate_type) and the processed
+        # one (op) so any divergence stays reconstructible.
+        writer.insert_archive_row(ArchiveRow(
+            source_file=fm.file,
+            source_table=lr.table_name,
+            source_log_id=lr.id,
+            record_id=lr.record_id,
+            target_schema=target_schema,
+            target_table=target_table,
+            original_operate_type=lr.operate_type,
+            processed_operate_type=op,
+            row_data=row_data,
+            original_time=lr.time,
+        ))
         qr = QueueRow(
             source_file=fm.file,
             source_table=lr.table_name,
             record_id=lr.record_id,
-            target_schema=fm.schema,
-            target_table=fm.target_table(lr.table_name),
+            target_schema=target_schema,
+            target_table=target_table,
             source_log_id=lr.id,
             operate_type=op,
             row_data=row_data,
         )
-        writer.insert_queue_row(qr)
-        n += 1
-    return n
+        if writer.insert_queue_row(qr):
+            st.enqueued += 1
+            st.note_op(op)
+        else:
+            # Dedup hit: this log row was already staged by an earlier cycle
+            # whose apply failed (the Access log row is only deleted after a
+            # successful apply). A persistently non-zero dedup count therefore
+            # points straight at a stuck apply -- see the queue-health WARNINGs
+            # emitted by sync.service.cycle.
+            st.dedup_skipped += 1
+            log.debug(
+                "capture dedup-skip (already queued) file=%s table=%s "
+                "log_id=%s record_id=%s op=%s",
+                fm.file, lr.table_name, lr.id, lr.record_id, op,
+            )
+
+    if st.read:
+        log.info(
+            "capture file=%s read=%d enqueued=%d dedup_skipped=%d "
+            "deferred=%d aged_out=%d out_of_scope=%d unknown_op=%d "
+            "log_ids=%s..%s ops={%s}",
+            fm.file, st.read, st.enqueued, st.dedup_skipped, st.deferred,
+            st.aged_out, st.out_of_scope, st.unknown_op, st.min_log_id,
+            st.max_log_id, st.ops_str(),
+        )
+    else:
+        log.debug("capture file=%s: change log empty", fm.file)
+    return st

src/sync/cleanup.py

@@ -1,10 +1,16 @@
 """Cleanup phase: delete applied Access log rows.
 
-After ``dbo.usp_SyncApply`` flips queue rows to ``applied``, those rows'
+After ``usp_SyncApply`` flips queue rows to ``applied``, those rows'
 ``SourceLogID`` values are no longer needed on the Access side. This module
 asks the writer which log IDs have been applied for a given source file and
 deletes them from ``TableChangeLog`` via the reader, in batches with lock
 retry. The delete is the only mutation that touches the Access side.
+
+Audit trail: the INFO line records the exact log-ID range removed from each
+file, and a WARNING is raised when fewer rows were deleted than expected --
+i.e. some applied log IDs were already absent from the Access log (removed
+externally, or by a previously interrupted run), which is worth knowing when
+reconstructing what happened around a divergence.
 """
 from __future__ import annotations
 import logging
@@ -28,9 +34,25 @@ def cleanup_file(fm: FileMapping, reader: AccessReader, writer: SqlWriter, cfg:
     """
     ids = writer.applied_log_ids(fm.file)
     if not ids:
+        log.debug("cleanup file=%s: no applied rows to clean", fm.file)
         return 0
+    log.debug("cleanup file=%s: deleting %d applied log rows ids=%s..%s",
+              fm.file, len(ids), ids[0], ids[-1])
     deleted = reader.delete_log_ids(
         ids, cfg.runtime.cleanup_batch_size, cfg.runtime.cleanup_lock_retries
     )
+    if deleted != len(ids):
+        log.warning(
+            "cleanup file=%s: deleted %d of %d applied log rows "
+            "(some log IDs were already absent from Access -- removed "
+            "externally or by an earlier interrupted run)",
+            fm.file, deleted, len(ids),
+        )
     writer.mark_cleaned(fm.file, ids)
+    if deleted:
+        log.info(
+            "cleanup file=%s: removed %d access log rows ids=%s..%s; "
+            "queue rows marked cleaned",
+            fm.file, deleted, ids[0], ids[-1],
+        )
     return deleted

src/sync/compare.py

@@ -11,7 +11,9 @@ as full sync -- empirically confirming the two stay aligned.
 """
 from __future__ import annotations
 
+import datetime as _dt
 import logging
+import os
 from dataclasses import dataclass, field
 
 from .config import FileMapping, SyncConfig
@@ -139,3 +141,52 @@ def format_report(results: list[TableResult], granularity: str = "count") -> str
         else:
             lines.append(f"{base}  access={r.access_count} sql={r.sql_count} [{r.status.upper()}]")
     return "\n".join(lines)
+
+
+def summarize(results: list[TableResult]) -> dict:
+    """Tally the outcome buckets: match / mismatch / skipped / error."""
+    s = {"match": 0, "mismatch": 0, "skipped": 0, "error": 0}
+    for r in results:
+        s[r.status] = s.get(r.status, 0) + 1
+    return s
+
+
+def write_report(results: list[TableResult], granularity: str = "count",
+                 log_dir: str = ".", run_dt: _dt.datetime | None = None,
+                 extra_path: str | None = None) -> str:
+    """Render the full report and persist it as a dated log file under *log_dir*.
+
+    Always writes ``<log_dir>/compare_<granularity>_<YYYY-MM-DD>.log``,
+    overwriting the day's previous run (one report per day; the logging system's
+    per-day archival later moves yesterday's file into ``logs/Archive/``). When
+    *extra_path* is given (the ``--report`` CLI option) the identical content is
+    also written there for backward compatibility. Returns the primary log path.
+    """
+    run_dt = run_dt or _dt.datetime.now()
+    stats = summarize(results)
+    body = format_report(results, granularity)
+    header = (
+        "============================================================\n"
+        " 数据一致性核对报告 / Compare Report\n"
+        f" 生成时间   : {run_dt.strftime('%Y-%m-%d %H:%M:%S')}\n"
+        f" 粒度       : {granularity}\n"
+        f" 比对表合计 : {stats['match'] + stats['mismatch']}\n"
+        f" 一致 MATCH : {stats['match']}\n"
+        f" 不一致 MISMATCH : {stats['mismatch']}\n"
+        f" 跳过 SKIPPED : {stats['skipped']}\n"
+        f" 错误 ERROR : {stats['error']}\n"
+        "============================================================\n"
+    )
+    report = header + body + "\n"
+
+    log_dir = log_dir or "."
+    os.makedirs(log_dir, exist_ok=True)
+    primary = os.path.join(
+        log_dir, f"compare_{granularity}_{run_dt.strftime('%Y-%m-%d')}.log"
+    )
+    with open(primary, "w", encoding="utf-8") as f:
+        f.write(report)
+    if extra_path:
+        with open(extra_path, "w", encoding="utf-8") as f:
+            f.write(report)
+    return primary

src/sync/config.py

@@ -5,7 +5,13 @@ from pydantic import BaseModel, ConfigDict, Field
 
 class SqlServerConfig(BaseModel):
     conn_str: str
-    sync_queue_table: str = "dbo.SyncQueue"
+    sync_queue_table: str = "ProductionDataBaseSync.SyncQueue"
+    archive_table: str = "ProductionDataBaseSync.SyncLogArchive"
+    apply_proc: str = "ProductionDataBaseSync.usp_SyncApply"
+    # Per-invocation, per-table apply audit written by usp_SyncApply
+    # (see sql/04_sync_apply_runlog.sql). Default matches the shipped script;
+    # existing config.yaml files need no change.
+    apply_runlog_table: str = "ProductionDataBaseSync.SyncApplyRunLog"
 
 class AccessConfig(BaseModel):
     model_config = ConfigDict(coerce_numbers_to_str=True)
@@ -21,6 +27,15 @@ class RuntimeConfig(BaseModel):
     cleanup_batch_size: int = 200
     cleanup_lock_retries: int = 3
     cleaned_retention_hours: int = 24
+    # Insert/Update 日志回读不到整行时，按 Access 日志的"年龄"（log_time 距今
+    # 秒数）决定动作：年龄小于此阈值视为 ACE 引擎的可见性延迟，跳过不入队
+    # （Access 日志保留，下一轮 cycle 重新捕获）；年龄达到此阈值仍读不到则
+    # 判定为真删除/异常，入队标 dead 待人工。根治"降级 Delete 致数据丢失"
+    # （见 docs/plan-capture-defer-by-age.md）。设为 0 关闭延迟重试。
+    capture_defer_seconds: int = 60
+    # Idle cycles now log at DEBUG; the service emits an INFO heartbeat at this
+    # interval while idle so a quiet log still proves the service is alive.
+    idle_heartbeat_seconds: int = 600
 
 class FileMapping(BaseModel):
     model_config = ConfigDict(coerce_numbers_to_str=True)

src/sync/logging_setup.py

@@ -2,10 +2,124 @@
 
 Configures the root logger with a RotatingFileHandler (10 MB x 5, UTF-8) plus
 a console StreamHandler. The level and log path come from ``cfg.logging``.
+
+Every record written to the log file carries a cycle correlation id
+(``[cyc:xxxxxxxx]``): ``sync.service.cycle`` allocates one per pass via
+``set_cycle_id`` and ``_CycleIdFilter`` injects it into each record, so every
+capture/apply/cleanup line of one pass -- and the matching
+``SyncApplyRunLog.CycleID`` rows on SQL Server -- can be correlated with a
+single grep. Outside a cycle (fullsync, compare, startup) the field is ``-``.
+
+Log files are managed per-day: at startup any previously produced log
+(including the project's own ``sync.log`` and NSSM's ``nssm_*.log`` captures)
+is relocated into an ``Archive/`` subfolder next to the active log. Where a log
+lacks a timestamp, a ``-YYYY-MM-DD`` suffix is added (derived from its first
+log line, falling back to mtime) so historical files carry a date. The log
+root therefore only ever shows the current day's ``sync.log``.
 """
+import contextvars
+import datetime
 import logging
 import logging.handlers
 import os
+import re
+import shutil
+
+
+_LOG_DATE_RE = re.compile(r"^(\d{4}-\d{2}-\d{2})")
+
+# Current cycle correlation id ("-" when not inside a service cycle).
+_cycle_id: contextvars.ContextVar[str] = contextvars.ContextVar(
+    "sync_cycle_id", default="-"
+)
+
+
+def set_cycle_id(cycle_id: str | None) -> None:
+    """Set (or clear, with ``None``) the id stamped on every log record.
+
+    Called by ``sync.service.cycle`` at the start/end of each pass. The same
+    id is passed to ``usp_SyncApply`` so SQL-side ``SyncApplyRunLog`` rows can
+    be joined back to the exact log lines of the cycle that produced them.
+    """
+    _cycle_id.set(cycle_id or "-")
+
+
+class _CycleIdFilter(logging.Filter):
+    """Inject the current cycle id into every record as ``record.cycle``.
+
+    Attached to the handlers (not the logger) so records emitted through any
+    module logger -- capture, cleanup, access_reader, ... -- are covered.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:  # noqa: A003
+        record.cycle = _cycle_id.get()
+        return True
+
+
+def _first_line_date(path: str) -> str | None:
+    """Best-effort extraction of the first log line's YYYY-MM-DD date."""
+    try:
+        with open(path, "r", encoding="utf-8", errors="replace") as f:
+            for line in f:
+                m = _LOG_DATE_RE.match(line)
+                if m:
+                    return m.group(1)
+    except OSError:
+        pass
+    return None
+
+
+def _archive_completed_logs(log_dir: str, active_name: str):
+    """Move already-produced logs out of *log_dir* into *log_dir*/Archive.
+
+    The active log (*active_name*) is left in place only when it belongs to the
+    current day; an older ``sync.log`` is archived (with a ``-YYYY-MM-DD``
+    suffix) so a fresh one can be opened. NSSM's own ``nssm_*.log`` captures are
+    timestamped already and are moved as-is. Moves are best-effort: files locked
+    by another process (e.g. NSSM's live handles) are skipped.
+    """
+    archive_dir = os.path.join(log_dir, "Archive")
+    os.makedirs(archive_dir, exist_ok=True)
+    today = datetime.date.today()
+
+    for name in os.listdir(log_dir):
+        src = os.path.join(log_dir, name)
+        if not os.path.isfile(src):
+            continue
+        if name == "Archive":
+            continue
+        if not (name.endswith(".log") or ".log." in name):
+            continue
+        # Keep NSSM's live, currently-open handles in place.
+        if name in ("nssm_stderr.log", "nssm_stdout.log"):
+            continue
+
+        if name == active_name:
+            # Only archive the active log if it is from a previous day.
+            log_date = _first_line_date(src)
+            log_date = (
+                datetime.date.fromisoformat(log_date)
+                if log_date
+                else datetime.date.fromtimestamp(os.path.getmtime(src))
+            )
+            if log_date >= today:
+                continue  # today's log: keep appending
+            new_name = f"sync-{log_date.strftime('%Y-%m-%d')}.log"
+        else:
+            new_name = name
+
+        dst = os.path.join(archive_dir, new_name)
+        if os.path.exists(dst):
+            stem, ext = os.path.splitext(new_name)
+            i = 2
+            while os.path.exists(os.path.join(archive_dir, f"{stem}({i}){ext}")):
+                i += 1
+            dst = os.path.join(archive_dir, f"{stem}({i}){ext}")
+        try:
+            shutil.move(src, dst)
+        except OSError:
+            # Locked by another process (e.g. NSSM holding the file open).
+            pass
 
 
 def setup_logging(cfg_dict: dict | None):
@@ -13,18 +127,45 @@ def setup_logging(cfg_dict: dict | None):
 
     ``cfg_dict`` is ``SyncConfig.logging`` (a dict or None). ``level`` is a
     logging-level name string (default ``"INFO"``); ``path`` is the log file
-    path (default ``"sync.log"``). The parent directory is created if missing.
+    path (default ``"sync.log"``). The parent directory is created if missing,
+    and any previously produced logs are archived before the new handler opens.
     """
     level = getattr(logging, (cfg_dict or {}).get("level", "INFO")) if cfg_dict else logging.INFO
     path = (cfg_dict or {}).get("path", "sync.log")
-    os.makedirs(os.path.dirname(path) or ".", exist_ok=True)
+    log_dir = os.path.dirname(path) or "."
+    os.makedirs(log_dir, exist_ok=True)
+
+    # Archive everything from prior runs so the root only shows today's log.
+    _archive_completed_logs(log_dir, os.path.basename(path))
+
+    # Idempotent: drop any handlers already attached to the root logger before
+    # re-adding. setup_logging can be called from more than one entry point
+    # (e.g. main.py and service.run), and the old code unconditionally
+    # addHandler'd each time, stacking duplicate handlers so every log line was
+    # written twice. Clearing first means repeated calls always yield exactly
+    # one file handler + one console handler, regardless of caller.
+    root = logging.getLogger()
+    for old in list(root.handlers):
+        root.removeHandler(old)
+        try:
+            old.close()
+        except Exception:
+            pass
+    root.setLevel(level)
+
+    cycle_filter = _CycleIdFilter()
+
     h = logging.handlers.RotatingFileHandler(
         path, maxBytes=10 * 1024 * 1024, backupCount=5, encoding="utf-8"
     )
-    h.setFormatter(logging.Formatter("%(asctime)s %(levelname)s [%(name)s] %(message)s"))
-    root = logging.getLogger()
-    root.setLevel(level)
+    h.addFilter(cycle_filter)
+    h.setFormatter(logging.Formatter(
+        "%(asctime)s %(levelname)s [%(name)s] [cyc:%(cycle)s] %(message)s"
+    ))
     root.addHandler(h)
+
     sh = logging.StreamHandler()
+    sh.addFilter(cycle_filter)
+    # Console keeps the short format (fullsync/compare are interactive there).
     sh.setFormatter(logging.Formatter("%(levelname)s %(message)s"))
     root.addHandler(sh)

src/sync/service.py

@@ -2,9 +2,24 @@
 
 ``cycle(cfg)`` runs one full pass over every configured file:
   1. capture  — read each file's change log and stage rows into SyncQueue;
-  2. apply    — drain the queue via ``dbo.usp_SyncApply``;
+  2. apply    — drain the queue via ``usp_SyncApply``;
   3. cleanup  — delete applied log rows from each file's Access log.
 
+Observability (rebuilt so data divergence is traceable from the log alone):
+- every cycle gets a short correlation id; ``logging_setup`` stamps it on each
+  log line as ``[cyc:xxxxxxxx]`` and the same id is passed to ``usp_SyncApply``
+  so ``SyncApplyRunLog`` rows on SQL Server join back to the exact log lines of
+  the cycle that produced them;
+- after apply, the per-table run-log rows (pending/merged/deleted/applied/
+  error/dead counts, duration, error message) are read back and logged --
+  the old single "apply done" line hid all of this;
+- queue health is checked every cycle: ``error``/``dead`` rows, which
+  previously accumulated in complete silence, now emit WARNINGs with per-row
+  samples (table, record id, retry count, error message) -- these are exactly
+  the changes that exist in Access but never reached SQL Server;
+- idle cycles log at DEBUG so INFO stays high-signal; ``run`` emits a periodic
+  idle heartbeat so a quiet log still proves the service is alive.
+
 Each file's capture and cleanup is wrapped in its own try/except so one
 file's failure is logged and the cycle continues; the writer is always closed
 in a ``finally``. ``run(cfg)`` loops ``cycle`` with a sleep; ``main()``
@@ -13,14 +28,15 @@ loads the config from ``argv[1]`` (default ``config.yaml``).
 from __future__ import annotations
 import sys
 import time
+import uuid
 import logging
 
 from .config import load_config
 from .access_reader import AccessReader
 from .sql_writer import SqlWriter
-from .capture import capture_file
+from .capture import capture_file, CaptureStats
 from .cleanup import cleanup_file
-from .logging_setup import setup_logging
+from .logging_setup import setup_logging, set_cycle_id
 
 log = logging.getLogger("sync.service")
 
@@ -30,47 +46,156 @@ def run(cfg):
 
     Configures logging once on entry. Intended to be started by ``main()``
     under the service host (e.g. NSSM). Not unit-tested (infinite loop);
-    ``cycle()`` is the testable unit.
+    ``cycle()`` is the testable unit. Emits an idle heartbeat every
+    ``runtime.idle_heartbeat_seconds`` so a quiet log still proves liveness
+    now that idle cycles log at DEBUG.
     """
     setup_logging(cfg.logging)
+    log.info(
+        "service started: files=%d poll_interval=%ds idle_heartbeat=%ds",
+        len(cfg.files), cfg.runtime.poll_interval_seconds,
+        cfg.runtime.idle_heartbeat_seconds,
+    )
+    idle_since = None
+    idle_cycles = 0
     while True:
-        cycle(cfg)
+        active = cycle(cfg)
+        now = time.monotonic()
+        if active:
+            idle_since, idle_cycles = None, 0
+        else:
+            idle_cycles += 1
+            if idle_since is None:
+                idle_since = now
+            elif now - idle_since >= cfg.runtime.idle_heartbeat_seconds:
+                log.info("idle heartbeat: %d cycles with no changes in the "
+                         "last %ds", idle_cycles, int(now - idle_since))
+                idle_since, idle_cycles = now, 0
         time.sleep(cfg.runtime.poll_interval_seconds)
 
 
-def cycle(cfg):
+def cycle(cfg) -> bool:
     """One capture -> apply -> cleanup pass over all files.
 
-    Per-file capture/cleanup failures are logged and do not abort the cycle.
-    Apply failure does not block cleanup. The writer is always closed in a
+    Returns True when the cycle did any work (captured / applied / cleaned /
+    purged anything); ``run`` uses this for idle-heartbeat pacing. Per-file
+    capture/cleanup failures are logged and do not abort the cycle. Apply
+    failure does not block cleanup. The writer is always closed in a
     ``finally``. Safe to call directly from tests (does not sleep or loop).
     """
-    writer = SqlWriter(cfg.sql_server.conn_str, cfg.sql_server.sync_queue_table)
+    cycle_id = uuid.uuid4().hex[:8]
+    set_cycle_id(cycle_id)
+    t0 = time.monotonic()
+    activity = False
+    writer = SqlWriter(
+        cfg.sql_server.conn_str,
+        cfg.sql_server.sync_queue_table,
+        cfg.sql_server.archive_table,
+        cfg.sql_server.apply_proc,
+        cfg.sql_server.apply_runlog_table,
+    )
     try:
-        total_captured = 0
+        # ---- capture ------------------------------------------------------
+        total = CaptureStats()
         for fm in cfg.files:
             reader = AccessReader(fm.source_path(cfg), cfg.access.driver)
             try:
-                n = capture_file(fm, reader, writer, cfg)
-                total_captured += n
+                total.merge(capture_file(fm, reader, writer, cfg))
             except Exception:
                 log.exception("capture failed for %s", fm.file)
             finally:
                 reader.close()
-        log.info("captured %d rows", total_captured)
+        if total.read:
+            activity = True
+            log.info(
+                "capture summary: read=%d enqueued=%d dedup_skipped=%d "
+                "deferred=%d aged_out=%d out_of_scope=%d unknown_op=%d ops={%s}",
+                total.read, total.enqueued, total.dedup_skipped,
+                total.deferred, total.aged_out, total.out_of_scope,
+                total.unknown_op, total.ops_str(),
+            )
+        else:
+            log.debug("capture summary: no new change-log rows in any file")
 
+        # ---- apply ----------------------------------------------------------
         try:
-            writer.call_apply(cfg.runtime.max_retries)
-            log.info("apply done")
+            writer.call_apply(cfg.runtime.max_retries, cycle_id)
+            runs = writer.apply_run_results(cycle_id)
+            if runs is None:
+                # Audit infra (SyncApplyRunLog / updated proc) not deployed
+                # yet: keep the legacy coarse line. sql_writer already warned
+                # once about what to deploy.
+                log.info("apply done")
+            elif not runs:
+                if total.enqueued:
+                    # Rows were staged but the proc wrote no audit rows: the
+                    # table exists but the deployed proc is probably the old
+                    # version that does not write into it.
+                    log.info("apply done (proc wrote no run-log rows -- "
+                             "re-run the updated sql/02_sync_apply.sql?)")
+                else:
+                    log.debug("apply done: queue was empty")
+            else:
+                activity = True
+                for r in runs:
+                    if r["Outcome"] == "ok":
+                        log.info(
+                            "apply ok table=%s.%s pending=%s records=%s "
+                            "merged=%s deleted=%s applied=%s dur_ms=%s",
+                            r["TargetSchema"], r["TargetTable"],
+                            r["PendingCount"], r["DistinctRecords"],
+                            r["MergedCount"], r["DeletedCount"],
+                            r["AppliedCount"], r["DurationMs"],
+                        )
+                    else:
+                        log.warning(
+                            "apply FAILED table=%s.%s pending=%s records=%s "
+                            "-> error=%s dead=%s dur_ms=%s msg=%s",
+                            r["TargetSchema"], r["TargetTable"],
+                            r["PendingCount"], r["DistinctRecords"],
+                            r["ErrorCount"], r["DeadCount"],
+                            r["DurationMs"], r["ErrorMsg"],
+                        )
         except Exception:
             log.exception("apply failed")
 
+        # ---- queue health ---------------------------------------------------
+        # error/dead rows are changes that exist in Access but never reached
+        # the SQL mirror. Before this check they accumulated with zero trace
+        # in this log -- the classic "data diverged, no idea why" scenario.
+        try:
+            status = writer.queue_status_summary()
+            stuck = status.get("error", 0) + status.get("dead", 0)
+            if stuck:
+                log.warning(
+                    "queue health: %d stuck row(s) [%s] -- these changes are "
+                    "NOT in SQL Server and will show up as data divergence",
+                    stuck,
+                    ",".join(f"{k}={v}" for k, v in sorted(status.items())),
+                )
+                for s in writer.queue_error_samples(10):
+                    log.warning(
+                        "  stuck row: table=%s.%s record_id=%s "
+                        "source_log_id=%s op=%s status=%s retries=%s "
+                        "captured_at=%s err=%s",
+                        s["TargetSchema"], s["TargetTable"], s["RecordID"],
+                        s["SourceLogID"], s["OperateType"], s["Status"],
+                        s["RetryCount"], s["CapturedAt"], s["ErrorMsg"],
+                    )
+            elif status.get("pending", 0):
+                log.warning(
+                    "queue health: %d row(s) still pending after apply "
+                    "(apply may have failed this cycle)", status["pending"],
+                )
+        except Exception:
+            log.exception("queue health check failed")
+
+        # ---- cleanup --------------------------------------------------------
         for fm in cfg.files:
             reader = AccessReader(fm.source_path(cfg), cfg.access.driver)
             try:
-                c = cleanup_file(fm, reader, writer, cfg)
-                if c:
-                    log.info("cleaned %d log rows from %s", c, fm.file)
+                if cleanup_file(fm, reader, writer, cfg):
+                    activity = True
             except Exception:
                 log.exception("cleanup failed for %s", fm.file)
             finally:
@@ -81,12 +206,18 @@ def cycle(cfg):
         try:
             purged = writer.purge_cleaned(cfg.runtime.cleaned_retention_hours)
             if purged:
-                log.info("purged %d cleaned queue rows", purged)
+                activity = True
+                log.info("purged %d cleaned queue rows (older than %dh)",
+                         purged, cfg.runtime.cleaned_retention_hours)
         except Exception:
             log.exception("purge failed")
 
+        (log.info if activity else log.debug)(
+            "cycle finished in %.2fs", time.monotonic() - t0)
+        return activity
     finally:
         writer.close()
+        set_cycle_id(None)
 
 
 def main():

src/sync/sql_writer.py

@@ -1,26 +1,50 @@
 """SQL-side writer for the Access -> SQL Server sync.
 
-SqlWriter owns the pyodbc connection used to (a) dedup-insert rows into
-``dbo.SyncQueue``, (b) invoke ``dbo.usp_SyncApply`` to drain the queue, and
-(c) report which SourceLogIDs have been applied.
+SqlWriter owns the pyodbc connection used to (a) dedup-insert rows into the
+staging queue (``ProductionDataBaseSync.SyncQueue`` by default), (b) invoke the
+apply proc (``ProductionDataBaseSync.usp_SyncApply``) to drain the queue,
+(c) report which SourceLogIDs have been applied, and (d) append every consumed
+Access change-log row to the permanent audit store
+(``ProductionDataBaseSync.SyncLogArchive``). The queue/archive/proc names are
+injected from config so the whole sync can live under a dedicated schema.
+
+Observability additions:
+- the dedup inserts now report whether a row was actually inserted (True) or
+  already present (False), so capture can log dedup hits -- the tell-tale of a
+  re-capture after a failed apply;
+- ``call_apply`` passes the service's cycle correlation id to the proc, which
+  records one audit row per target table into
+  ``ProductionDataBaseSync.SyncApplyRunLog`` (see sql/04_sync_apply_runlog.sql);
+- ``apply_run_results`` reads those rows back so the service log shows
+  per-table merged/deleted/applied/error/dead counts instead of "apply done";
+- ``queue_status_summary`` / ``queue_error_samples`` surface stuck
+  (``error``/``dead``) queue rows, which previously accumulated silently.
 
 The connection is opened with ``autocommit=True`` on purpose. ``usp_SyncApply``
 manages its own transaction internally (BEGIN TRAN ... ROLLBACK on error); if
 the caller held an outer implicit transaction, the proc's ROLLBACK would
-cascade and raise SQL error 266. The dedup ``IF NOT EXISTS ... INSERT`` is a
-single statement that is atomic under autocommit, so no explicit transaction is
-needed on the write path either.
+cascade and raise SQL error 266. The dedup ``INSERT .. SELECT .. WHERE NOT
+EXISTS`` is a single statement that is atomic under autocommit, so no explicit
+transaction is needed on the write path either.
 """
 from __future__ import annotations
 
+import logging
 from dataclasses import dataclass
 
 import pyodbc
 
+log = logging.getLogger(__name__)
+
+# Process-wide deployment-state flags (SqlWriter instances are recreated every
+# cycle, so per-instance flags would re-warn each cycle).
+_proc_lacks_cycle_id = False   # deployed usp_SyncApply predates @CycleID
+_runlog_missing_noted = False  # SyncApplyRunLog table not deployed yet
+
 
 @dataclass
 class QueueRow:
-    """A single staged change to enqueue into ``dbo.SyncQueue``."""
+    """A single staged change to enqueue into the SyncQueue table."""
 
     source_file: str
     source_table: str
@@ -32,35 +56,67 @@ class QueueRow:
     row_data: str | None
 
 
-class SqlWriter:
-    """Writes to SyncQueue and drives the apply proc over a pyodbc connection."""
+@dataclass
+class ArchiveRow:
+    """A single Access change-log row to append to ``SyncLogArchive``.
 
-    def __init__(self, conn_str: str, queue_table: str = "dbo.SyncQueue"):
+    Captures both the ORIGINAL operate type recorded by the Access data macro
+    and the PROCESSED operate type actually sent to the queue, so a downgrade
+    (e.g. Insert -> Delete when the row is momentarily unreadable) stays visible
+    forever. ``original_time`` preserves the Access log's own timestamp, which
+    the queue path discards.
+    """
+
+    source_file: str
+    source_table: str
+    source_log_id: int
+    record_id: str
+    target_schema: str
+    target_table: str
+    original_operate_type: str
+    processed_operate_type: str
+    row_data: str | None
+    original_time: object
+
+
+class SqlWriter:
+    """Writes to SyncQueue/SyncLogArchive and drives the apply proc."""
+
+    def __init__(
+        self,
+        conn_str: str,
+        queue_table: str = "ProductionDataBaseSync.SyncQueue",
+        archive_table: str = "ProductionDataBaseSync.SyncLogArchive",
+        apply_proc: str = "ProductionDataBaseSync.usp_SyncApply",
+        runlog_table: str = "ProductionDataBaseSync.SyncApplyRunLog",
+    ):
         self.conn_str = conn_str
         self.queue_table = queue_table
+        self.archive_table = archive_table
+        self.apply_proc = apply_proc
+        self.runlog_table = runlog_table
         # autocommit=True: usp_SyncApply manages its own transaction internally.
         # An outer pyodbc transaction would conflict on ROLLBACK (SQL error 266).
         self._conn = pyodbc.connect(conn_str, autocommit=True)
 
-    def insert_queue_row(self, row: QueueRow) -> None:
+    def insert_queue_row(self, row: QueueRow) -> bool:
         """Idempotently enqueue ``row`` (dedup on SourceFile/Table/LogID).
 
-        ``IF NOT EXISTS ... INSERT`` is a single statement, atomic under
-        autocommit. The unique index UX_SyncQueue_Dedup is the DB backstop.
+        Returns True when a new queue row was inserted, False on a dedup hit
+        (the row was already staged -- typically a re-capture after a failed
+        apply left the Access log row in place). ``INSERT .. SELECT .. WHERE
+        NOT EXISTS`` is a single statement, atomic under autocommit, and its
+        deterministic rowcount (0/1) is what makes the dedup outcome
+        observable for the capture audit log. The unique index
+        UX_SyncQueue_Dedup is the DB backstop.
         """
-        # IF NOT EXISTS and the VALUES list each carry their own ? markers;
-        # pyodbc binds them positionally, so the 3 dedup keys are supplied
-        # twice (once for the EXISTS check, once for the INSERT).
         cur = self._conn.cursor()
         cur.execute(
-            "IF NOT EXISTS (SELECT 1 FROM dbo.SyncQueue "
-            "WHERE SourceFile=? AND SourceTable=? AND SourceLogID=?) "
-            "INSERT dbo.SyncQueue(SourceFile,SourceTable,SourceLogID,"
+            f"INSERT INTO {self.queue_table}(SourceFile,SourceTable,SourceLogID,"
             "TargetSchema,TargetTable,RecordID,OperateType,RowData,Status) "
-            "VALUES (?,?,?,?,?,?,?,?, 'pending')",
-            row.source_file,
-            row.source_table,
-            row.source_log_id,
+            "SELECT ?,?,?,?,?,?,?,?,'pending' "
+            f"WHERE NOT EXISTS (SELECT 1 FROM {self.queue_table} "
+            "WHERE SourceFile=? AND SourceTable=? AND SourceLogID=?)",
             row.source_file,
             row.source_table,
             row.source_log_id,
@@ -69,22 +125,176 @@ class SqlWriter:
             row.record_id,
             row.operate_type,
             row.row_data,
+            row.source_file,
+            row.source_table,
+            row.source_log_id,
         )
         # autocommit: statement already committed.
+        return cur.rowcount > 0
 
-    def call_apply(self, max_retries: int) -> None:
-        """Drain the pending queue via the stored procedure.
+    def insert_dead_row(self, row: QueueRow, error_msg: str) -> bool:
+        """Enqueue ``row`` then immediately mark it ``dead`` (never applied).
 
-        ``usp_SyncApply`` flips rows to ``applied`` (or ``error`` after retries).
+        Used by capture for an Insert/Update log whose source row stays
+        unreadable past the defer window (``capture_defer_seconds``): the row
+        is recorded for audit/health-alerting purposes but never executed by
+        ``usp_SyncApply`` (which only selects ``Status='pending'``), so no
+        destructive SQL ever runs against the mirror table. The OperateType is
+        preserved as the original Insert/Update so the intent stays visible,
+        while ErrorMsg explains why it was parked.
+
+        Dedup semantics match ``insert_queue_row``: if the (SourceFile,
+        SourceTable, SourceLogID) row already exists, the insert is skipped
+        and the existing row is re-marked dead. Returns True when a new row
+        was inserted, False on a dedup hit (the re-mark still happens).
+        """
+        inserted = self.insert_queue_row(row)
+        cur = self._conn.cursor()
+        cur.execute(
+            f"UPDATE {self.queue_table} SET Status='dead', ErrorMsg=? "
+            "WHERE SourceFile=? AND SourceTable=? AND SourceLogID=?",
+            error_msg,
+            row.source_file,
+            row.source_table,
+            row.source_log_id,
+        )
+        # autocommit: statement already committed.
+        return inserted
+
+    def insert_archive_row(self, row: ArchiveRow) -> bool:
+        """Append ``row`` to the permanent audit store (dedup on source keys).
+
+        Written during capture, BEFORE cleanup deletes the Access log, so the
+        original evidence survives even after the queue row is purged. Stores
+        both the original and processed operate types plus the Access log time.
+        The ``WHERE NOT EXISTS`` guard keeps the first archive record if
+        capture re-runs the same log id (a prior cycle's apply failed and the
+        Access log persisted). Returns True when a new archive row was
+        written, False on a dedup hit.
         """
         cur = self._conn.cursor()
-        cur.execute("EXEC dbo.usp_SyncApply ?", max_retries)
+        cur.execute(
+            f"INSERT INTO {self.archive_table}(SourceFile,SourceTable,SourceLogID,"
+            "RecordID,TargetSchema,TargetTable,OriginalOperateType,"
+            "ProcessedOperateType,RowData,OriginalTime) "
+            "SELECT ?,?,?,?,?,?,?,?,?,? "
+            f"WHERE NOT EXISTS (SELECT 1 FROM {self.archive_table} "
+            "WHERE SourceFile=? AND SourceTable=? AND SourceLogID=?)",
+            row.source_file,
+            row.source_table,
+            row.source_log_id,
+            row.record_id,
+            row.target_schema,
+            row.target_table,
+            row.original_operate_type,
+            row.processed_operate_type,
+            row.row_data,
+            row.original_time,
+            row.source_file,
+            row.source_table,
+            row.source_log_id,
+        )
+        # autocommit: statement already committed.
+        return cur.rowcount > 0
+
+    def call_apply(self, max_retries: int, cycle_id: str | None = None) -> None:
+        """Drain the pending queue via the stored procedure.
+
+        ``usp_SyncApply`` flips rows to ``applied`` (or ``error``/``dead``
+        after retries) and -- once the updated proc plus the SyncApplyRunLog
+        table are deployed -- writes one audit row per target table tagged
+        with ``cycle_id``, so SQL-side apply stats join back to the service
+        log's ``[cyc:...]`` lines. Falls back to the legacy single-parameter
+        signature when the deployed proc predates ``@CycleID`` (SQL errors
+        8144/8145), so rolling out the Python side first keeps working.
+        """
+        global _proc_lacks_cycle_id
+        cur = self._conn.cursor()
+        if cycle_id is not None and not _proc_lacks_cycle_id:
+            try:
+                cur.execute(
+                    f"EXEC {self.apply_proc} @MaxRetries=?, @CycleID=?",
+                    max_retries, cycle_id,
+                )
+                return
+            except pyodbc.Error as e:
+                msg = str(e)
+                if "8144" in msg or "8145" in msg:
+                    _proc_lacks_cycle_id = True
+                    log.warning(
+                        "apply proc %s does not accept @CycleID yet -- run the "
+                        "updated sql/02_sync_apply.sql to enable per-table "
+                        "apply auditing; falling back to the legacy signature",
+                        self.apply_proc,
+                    )
+                else:
+                    raise
+        cur.execute(f"EXEC {self.apply_proc} ?", max_retries)
+
+    def apply_run_results(self, cycle_id: str) -> list[dict] | None:
+        """Per-table apply outcomes recorded by the proc for ``cycle_id``.
+
+        Reads ``SyncApplyRunLog`` (pending/distinct counts, MERGE/DELETE
+        rowcounts, applied/error/dead queue-row counts, duration and error
+        message per target table). Returns ``None`` when the audit
+        infrastructure is not deployed yet (legacy proc, or table missing) so
+        the caller can fall back to coarse logging; returns ``[]`` when the
+        queue was simply empty.
+        """
+        global _runlog_missing_noted
+        if _proc_lacks_cycle_id:
+            return None  # legacy proc never writes run-log rows
+        cur = self._conn.cursor()
+        try:
+            cur.execute(
+                "SELECT TargetSchema,TargetTable,PendingCount,DistinctRecords,"
+                "MergedCount,DeletedCount,AppliedCount,ErrorCount,DeadCount,"
+                "Outcome,ErrorMsg,StartedAt,DurationMs "
+                f"FROM {self.runlog_table} WHERE CycleID=? ORDER BY RunLogID",
+                cycle_id,
+            )
+        except pyodbc.Error:
+            if not _runlog_missing_noted:
+                _runlog_missing_noted = True
+                log.warning(
+                    "run-log table %s not available -- run "
+                    "sql/04_sync_apply_runlog.sql to enable per-table apply "
+                    "stats in this log", self.runlog_table,
+                )
+            return None
+        cols = [c[0] for c in cur.description]
+        return [dict(zip(cols, r)) for r in cur.fetchall()]
+
+    def queue_status_summary(self) -> dict[str, int]:
+        """Row counts per Status (pending/applied/error/dead/cleaned)."""
+        cur = self._conn.cursor()
+        cur.execute(
+            f"SELECT Status, COUNT(*) FROM {self.queue_table} GROUP BY Status"
+        )
+        return {r[0]: r[1] for r in cur.fetchall()}
+
+    def queue_error_samples(self, limit: int = 10) -> list[dict]:
+        """Most recent ``error``/``dead`` queue rows, for WARNING-level triage.
+
+        These are exactly the changes that exist in Access but never reached
+        the SQL mirror -- the prime suspects for any data divergence.
+        """
+        cur = self._conn.cursor()
+        cur.execute(
+            "SELECT TOP (?) TargetSchema,TargetTable,RecordID,SourceLogID,"
+            "OperateType,Status,RetryCount,ErrorMsg,CapturedAt "
+            f"FROM {self.queue_table} WHERE Status IN ('error','dead') "
+            "ORDER BY QueueID DESC",
+            limit,
+        )
+        cols = [c[0] for c in cur.description]
+        return [dict(zip(cols, r)) for r in cur.fetchall()]
 
     def applied_log_ids(self, source_file: str) -> list[int]:
         """Return applied SourceLogIDs for ``source_file`` in ascending order."""
         cur = self._conn.cursor()
         cur.execute(
-            "SELECT SourceLogID FROM dbo.SyncQueue "
+            f"SELECT SourceLogID FROM {self.queue_table} "
             "WHERE SourceFile=? AND Status='applied' ORDER BY SourceLogID",
             source_file,
         )
@@ -107,7 +317,7 @@ class SqlWriter:
             chunk = source_log_ids[i:i + 1000]
             placeholders = ",".join("?" * len(chunk))
             cur.execute(
-                f"UPDATE dbo.SyncQueue SET Status='cleaned', "
+                f"UPDATE {self.queue_table} SET Status='cleaned', "
                 f"CleanedAt=sysdatetime() "
                 f"WHERE SourceFile=? AND Status='applied' "
                 f"AND SourceLogID IN ({placeholders})",
@@ -120,12 +330,12 @@ class SqlWriter:
 
         Keeps the table bounded: cleanup marks rows ``cleaned`` every cycle,
         and this removes the old ones after a short audit/debug window so
-        ``dbo.SyncQueue`` stops growing without bound. Returns the number of
+        the queue table stops growing without bound. Returns the number of
         rows removed.
         """
         cur = self._conn.cursor()
         cur.execute(
-            "DELETE FROM dbo.SyncQueue "
+            f"DELETE FROM {self.queue_table} "
             "WHERE Status='cleaned' "
             "AND CleanedAt < DATEADD(hour, -?, GETDATE())",
             retention_hours,

tests/test_apply_proc.py

@@ -1,15 +1,23 @@
-"""Integration test for dbo.usp_SyncApply.
+"""Integration test for usp_SyncApply.
 
 Validates: IDENTITY-preserving INSERT, last-write-wins UPDATE, BIT conversion
 from JSON ``true``/``false``, and DELETE of the last op. Creates a throwaway
 schema ``sync_test`` and table ``ApplyDemo_YEAR2026`` and cleans them up at the
 end so no residue is left on CompanyDB.
+
+Queue table and apply proc names are read from ``config.yaml`` so the test
+follows whichever schema the deployment targets (currently ProductionDataBaseSync).
 """
 import pytest
 
+from sync.config import load_config
+
 
 @pytest.mark.integration
 def test_upsert_insert_update_delete_last_write_wins(sql_conn):
+    cfg = load_config("config.yaml")
+    qt = cfg.sql_server.sync_queue_table
+    proc = cfg.sql_server.apply_proc
     cur = sql_conn.cursor()
     sch, tbl = "sync_test", "ApplyDemo_YEAR2026"
 
@@ -27,17 +35,17 @@ def test_upsert_insert_update_delete_last_write_wins(sql_conn):
         "时间 DATETIME2 NULL, "
         "标记 BIT NULL)"
     )
-    cur.execute("DELETE dbo.SyncQueue WHERE TargetSchema='sync_test'")
+    cur.execute("DELETE " + qt + " WHERE TargetSchema='sync_test'")
 
     # Insert then a later Update for the same RecordID=1 -> last write wins.
     cur.execute(
-        "INSERT dbo.SyncQueue(SourceFile,SourceTable,SourceLogID,TargetSchema,"
+        "INSERT " + qt + "(SourceFile,SourceTable,SourceLogID,TargetSchema,"
         "TargetTable,RecordID,OperateType,RowData,Status) "
         "VALUES('t.accdb','ApplyDemo',1,'sync_test','ApplyDemo_YEAR2026','1',"
         "'Insert','{\"ID\":1,\"名字\":\"A\",\"数量\":3,\"时间\":\"2026-01-01T00:00:00\",\"标记\":true}','pending')"
     )
     cur.execute(
-        "INSERT dbo.SyncQueue(SourceFile,SourceTable,SourceLogID,TargetSchema,"
+        "INSERT " + qt + "(SourceFile,SourceTable,SourceLogID,TargetSchema,"
         "TargetTable,RecordID,OperateType,RowData,Status) "
         "VALUES('t.accdb','ApplyDemo',2,'sync_test','ApplyDemo_YEAR2026','1',"
         "'Update','{\"ID\":1,\"名字\":\"A2\",\"数量\":5,\"时间\":\"2026-01-02T00:00:00\",\"标记\":false}','pending')"
@@ -45,7 +53,7 @@ def test_upsert_insert_update_delete_last_write_wins(sql_conn):
     sql_conn.commit()
 
     # --- Act 1: apply upsert ----------------------------------------------
-    cur.execute("EXEC dbo.usp_SyncApply @MaxRetries=5")
+    cur.execute("EXEC " + proc + " @MaxRetries=5")
     sql_conn.commit()
 
     # --- Assert 1: the later Update wins; BIT false -> 0 ------------------
@@ -57,15 +65,15 @@ def test_upsert_insert_update_delete_last_write_wins(sql_conn):
     assert row.标记 == 0  # BIT false
 
     # --- Act 2: a later Delete wins ---------------------------------------
-    cur.execute("DELETE dbo.SyncQueue WHERE TargetSchema='sync_test'")
+    cur.execute("DELETE " + qt + " WHERE TargetSchema='sync_test'")
     cur.execute(
-        "INSERT dbo.SyncQueue(SourceFile,SourceTable,SourceLogID,TargetSchema,"
+        "INSERT " + qt + "(SourceFile,SourceTable,SourceLogID,TargetSchema,"
         "TargetTable,RecordID,OperateType,RowData,Status) "
         "VALUES('t.accdb','ApplyDemo',3,'sync_test','ApplyDemo_YEAR2026','1',"
         "'Delete',NULL,'pending')"
     )
     sql_conn.commit()
-    cur.execute("EXEC dbo.usp_SyncApply @MaxRetries=5")
+    cur.execute("EXEC " + proc + " @MaxRetries=5")
     sql_conn.commit()
 
     # --- Assert 2: row removed --------------------------------------------
@@ -77,5 +85,5 @@ def test_upsert_insert_update_delete_last_write_wins(sql_conn):
         "IF OBJECT_ID('sync_test.ApplyDemo_YEAR2026') IS NOT NULL "
         "DROP TABLE sync_test.ApplyDemo_YEAR2026"
     )
-    cur.execute("DELETE dbo.SyncQueue WHERE TargetSchema='sync_test'")
+    cur.execute("DELETE " + qt + " WHERE TargetSchema='sync_test'")
     sql_conn.commit()

tests/test_capture.py

@@ -1,23 +1,34 @@
+import datetime as _dt
 from unittest.mock import MagicMock
+
 from sync.config import FileMapping, SyncConfig, AccessConfig, RuntimeConfig, SqlServerConfig
 from sync.access_reader import LogRow
 from sync.capture import capture_file
 
-def _cfg():
+
+def _cfg(defer=60):
     return SyncConfig(sql_server=SqlServerConfig(conn_str="x"),
-                      access=AccessConfig(driver="d", roots={"2026":"r"}),
-                      runtime=RuntimeConfig(),
+                      access=AccessConfig(driver="d", roots={"2026": "r"}),
+                      runtime=RuntimeConfig(capture_defer_seconds=defer),
                       files=[])
 
+
+def _fm():
+    return FileMapping(file="x.accdb", root="2026", schema="s",
+                       year_suffix="_YEAR2026", exclude_tables=["TableChangeLog"])
+
+
 def test_capture_insert_reads_row_and_queues():
     cfg = _cfg()
-    fm = FileMapping(file="氩弧焊.accdb", root="2026", schema="TIGWelding", year_suffix="_YEAR2026", exclude_tables=["TableChangeLog"])
+    fm = FileMapping(file="氩弧焊.accdb", root="2026", schema="TIGWelding",
+                     year_suffix="_YEAR2026", exclude_tables=["TableChangeLog"])
     reader = MagicMock()
-    reader.read_log.return_value = [LogRow(10, "表壳焊接记录", "34041", "Insert", None)]
+    reader.read_log.return_value = [LogRow(10, "表壳焊接记录", "34041", "Insert", _dt.datetime.now())]
     reader.read_row.return_value = {"ID": 34041, "订单号": "X1"}
     writer = MagicMock()
-    n = capture_file(fm, reader, writer, cfg)
-    assert n == 1
+    st = capture_file(fm, reader, writer, cfg)
+    assert st.enqueued == 1
+    assert st.deferred == 0 and st.aged_out == 0
     args = writer.insert_queue_row.call_args[0][0]
     assert args.target_schema == "TIGWelding"
     assert args.target_table == "表壳焊接记录_YEAR2026"
@@ -25,37 +36,106 @@ def test_capture_insert_reads_row_and_queues():
     assert '"订单号": "X1"' in args.row_data
     assert args.source_log_id == 10
 
-def test_capture_update_missing_row_downgrades_to_delete():
-    cfg = _cfg()
-    fm = FileMapping(file="x.accdb", root="2026", schema="s", year_suffix="_YEAR2026", exclude_tables=["TableChangeLog"])
+
+def test_capture_unreadable_young_row_is_deferred():
+    # Insert 日志年龄 < capture_defer_seconds → 跳过，不入队、不写 archive
+    cfg = _cfg(defer=60)
     reader = MagicMock()
-    reader.read_log.return_value = [LogRow(11, "T", "5", "Update", None)]
-    reader.read_row.return_value = None  # 行已删
+    reader.read_log.return_value = [LogRow(11, "T", "5", "Insert", _dt.datetime.now())]
+    reader.read_row.return_value = None  # 回读不到
     writer = MagicMock()
-    n = capture_file(fm, reader, writer, cfg)
-    assert n == 1
-    args = writer.insert_queue_row.call_args[0][0]
-    assert args.operate_type == "Delete"
-    assert args.row_data is None
+    st = capture_file(_fm(), reader, writer, cfg)
+    assert st.deferred == 1
+    assert st.enqueued == 0 and st.aged_out == 0
+    writer.insert_queue_row.assert_not_called()
+    writer.insert_dead_row.assert_not_called()
+    writer.insert_archive_row.assert_not_called()
+
+
+def test_capture_unreadable_young_update_also_deferred():
+    # Update 同样走 defer 路径（不降级 Delete）
+    cfg = _cfg(defer=60)
+    reader = MagicMock()
+    reader.read_log.return_value = [LogRow(12, "T", "6", "Update", _dt.datetime.now())]
+    reader.read_row.return_value = None
+    writer = MagicMock()
+    st = capture_file(_fm(), reader, writer, cfg)
+    assert st.deferred == 1
+    writer.insert_queue_row.assert_not_called()
+    writer.insert_dead_row.assert_not_called()
+
+
+def test_capture_unreadable_aged_row_marked_dead():
+    # Insert 日志年龄 >= capture_defer_seconds → 入队标 dead，不执行破坏性 SQL
+    cfg = _cfg(defer=60)
+    old_time = _dt.datetime.now() - _dt.timedelta(seconds=200)
+    reader = MagicMock()
+    reader.read_log.return_value = [LogRow(13, "T", "7", "Insert", old_time)]
+    reader.read_row.return_value = None  # 仍读不到
+    writer = MagicMock()
+    st = capture_file(_fm(), reader, writer, cfg)
+    assert st.aged_out == 1
+    assert st.enqueued == 0 and st.deferred == 0
+    # archive 留痕（ProcessedOperateType=AgedOut）
+    arch = writer.insert_archive_row.call_args[0][0]
+    assert arch.original_operate_type == "Insert"
+    assert arch.processed_operate_type == "AgedOut"
+    assert arch.row_data is None
+    # 入队标 dead，OperateType 保留原始 Insert
+    qr, err = writer.insert_dead_row.call_args[0]
+    assert qr.operate_type == "Insert"   # 不降级
+    assert qr.row_data is None
+    assert "200s" in err
+
+
+def test_capture_defer_zero_disables_retry():
+    # capture_defer_seconds=0 → 任何读不到都立即判死（边界）
+    cfg = _cfg(defer=0)
+    reader = MagicMock()
+    reader.read_log.return_value = [LogRow(14, "T", "8", "Insert", _dt.datetime.now())]
+    reader.read_row.return_value = None
+    writer = MagicMock()
+    st = capture_file(_fm(), reader, writer, cfg)
+    assert st.aged_out == 1
+    assert st.deferred == 0
+
+
+def test_capture_delete_never_reads_row():
+    # Delete 日志无需回读，直接入队
+    cfg = _cfg()
+    reader = MagicMock()
+    reader.read_log.return_value = [LogRow(15, "T", "9", "Delete", _dt.datetime.now())]
+    writer = MagicMock()
+    st = capture_file(_fm(), reader, writer, cfg)
+    assert st.enqueued == 1
+    reader.read_row.assert_not_called()
+    qr = writer.insert_queue_row.call_args[0][0]
+    assert qr.operate_type == "Delete"
+    assert qr.row_data is None
+
 
 def test_capture_skips_excluded_tables():
     cfg = _cfg()
-    fm = FileMapping(file="x.accdb", root="2026", schema="s", year_suffix="_YEAR2026", exclude_tables=["TableChangeLog", "氩弧焊每日催货落实记录_停"])
+    fm = FileMapping(file="x.accdb", root="2026", schema="s", year_suffix="_YEAR2026",
+                     exclude_tables=["TableChangeLog", "氩弧焊每日催货落实记录_停"])
     reader = MagicMock()
-    reader.read_log.return_value = [LogRow(1, "TableChangeLog", "1", "Insert", None),
-                                    LogRow(2, "氩弧焊每日催货落实记录_停", "1", "Insert", None)]
+    reader.read_log.return_value = [LogRow(1, "TableChangeLog", "1", "Insert", _dt.datetime.now()),
+                                    LogRow(2, "氩弧焊每日催货落实记录_停", "1", "Insert", _dt.datetime.now())]
     writer = MagicMock()
-    assert capture_file(fm, reader, writer, cfg) == 0
+    st = capture_file(fm, reader, writer, cfg)
+    assert st.enqueued == 0 and st.out_of_scope == 2
     writer.insert_queue_row.assert_not_called()
 
+
 def test_capture_include_tables_filter():
     cfg = _cfg()
     fm = FileMapping(file="x.accdb", root="2026", schema="inspectionRecords", year_suffix="_YEAR2026",
                      exclude_tables=["TableChangeLog"], include_tables=["检验合格记录表"])
     reader = MagicMock()
-    reader.read_log.return_value = [LogRow(1, "检验合格记录表", "1", "Insert", None),
-                                    LogRow(2, "其它表", "1", "Insert", None)]
+    reader.read_log.return_value = [LogRow(1, "检验合格记录表", "1", "Insert", _dt.datetime.now()),
+                                    LogRow(2, "其它表", "1", "Insert", _dt.datetime.now())]
     reader.read_row.return_value = {"ID": 1}
     writer = MagicMock()
-    assert capture_file(fm, reader, writer, cfg) == 1
+    st = capture_file(fm, reader, writer, cfg)
+    assert st.enqueued == 1
     assert writer.insert_queue_row.call_args[0][0].target_table == "检验合格记录表_YEAR2026"

tests/test_sql_writer.py

@@ -21,10 +21,16 @@ def test_insert_dedup_and_applied_ids():
     if not os.environ.get("RUN_INTEGRATION"):
         pytest.skip("integration")
     cfg = load_config("config.yaml")
-    w = SqlWriter(cfg.sql_server.conn_str, "dbo.SyncQueue")
+    qt = cfg.sql_server.sync_queue_table
+    w = SqlWriter(
+        cfg.sql_server.conn_str,
+        qt,
+        cfg.sql_server.archive_table,
+        cfg.sql_server.apply_proc,
+    )
     try:
         cur = w._conn.cursor()
-        cur.execute("DELETE dbo.SyncQueue WHERE SourceFile='sqlw_test.accdb'")
+        cur.execute(f"DELETE {qt} WHERE SourceFile='sqlw_test.accdb'")
         qr = QueueRow(
             source_file="sqlw_test.accdb",
             source_table="T",
@@ -38,7 +44,7 @@ def test_insert_dedup_and_applied_ids():
         w.insert_queue_row(qr)
         w.insert_queue_row(qr)  # duplicate must be deduped (ignored)
         cur.execute(
-            "SELECT COUNT(*) FROM dbo.SyncQueue "
+            f"SELECT COUNT(*) FROM {qt} "
             "WHERE SourceFile='sqlw_test.accdb' AND SourceLogID=100"
         )
         assert cur.fetchone()[0] == 1
@@ -47,12 +53,12 @@ def test_insert_dedup_and_applied_ids():
         w.call_apply(max_retries=5)
 
         cur.execute(
-            "UPDATE dbo.SyncQueue SET Status='applied' "
+            f"UPDATE {qt} SET Status='applied' "
             "WHERE SourceFile='sqlw_test.accdb'"
         )
         assert w.applied_log_ids("sqlw_test.accdb") == [100]
     finally:
-        cur.execute("DELETE dbo.SyncQueue WHERE SourceFile='sqlw_test.accdb'")
+        cur.execute(f"DELETE {qt} WHERE SourceFile='sqlw_test.accdb'")
         w.close()