diff --git a/docs/problems/IM-R11-Traefik入口故障运维排查手册-20261004.md b/docs/problems/IM-R11-Traefik入口故障运维排查手册-20261004.md new file mode 100644 index 0000000..8e81021 --- /dev/null +++ b/docs/problems/IM-R11-Traefik入口故障运维排查手册-20261004.md @@ -0,0 +1,226 @@ +# IM R11 Traefik 入口故障运维排查手册 + +## 1. 目标与已知事实 + +需要定位 2026-10-04 北京时间 `10:39:30–10:42:30`,即 UTC `02:39:30–02:42:30` 的入口整体中断。 + +已知现象: + +- `api.118im.com/metrics` 先后出现超时、HTTP 521 和 HTTP 503。 +- 三个源 IP 的 443 在约 10:40:16 同时 `connection refused`。 +- 2000 个 WebSocket 几乎同时断开,A/B 两台压测机均受影响。 +- Tinode cluster 采样仍为 2/2 live peers。 +- 故障后三个源 IP 返回同一张 `TRAEFIK DEFAULT CERT`,证书 `notBefore` 为 `2026-10-04 10:41:32 +08:00`,与入口恢复窗口重合。 +- 运维已确认 `216.236.31.189:6443` 按安全策略不对公网开放,只允许集群网络访问;外部调试机 TCP 超时属于预期行为。 + +排查过程中不要先重启 Traefik、节点或 k3s,也不要清理容器和日志。先完成只读取证。 + +## 2. 运维进入方式 + +优先在控制面节点直接执行 `kubectl`。如果控制面节点没有配置 kubeconfig,k3s 通常可使用: + +```bash +sudo k3s kubectl get nodes -o wide +``` + +普通 Kubernetes 可使用: + +```bash +kubectl get nodes -o wide +kubectl cluster-info +``` + +不建议把 6443 直接向公网完全开放。长期方案应采用 VPN/堡垒机或仅允许固定运维出口 IP。短期也可以让运维直接在控制面节点采集下面的结果。 + +## 3. 第一优先级:确认 Traefik 是否重启 + +先找到 Traefik 所在 namespace、工作负载和 Pod: + +```bash +kubectl get deploy,ds,sts,pod -A -o wide | grep -i traefik +kubectl get pods -A -l app.kubernetes.io/name=traefik -o wide +kubectl get pods -A -l app=traefik -o wide +``` + +对每个 Traefik Pod 执行: + +```bash +kubectl -n kube-system get pod TRAEFIK_POD -o jsonpath='{.metadata.name}{"\nstarted="}{.status.startTime}{"\nrestarts="}{.status.containerStatuses[*].restartCount}{"\nlastReason="}{.status.containerStatuses[*].lastState.terminated.reason}{"\nlastExit="}{.status.containerStatuses[*].lastState.terminated.exitCode}{"\nlastFinished="}{.status.containerStatuses[*].lastState.terminated.finishedAt}{"\n"}' + +kubectl -n kube-system describe pod TRAEFIK_POD +kubectl -n kube-system logs TRAEFIK_POD --all-containers --timestamps --since-time=2026-10-04T02:39:30Z +kubectl -n kube-system logs TRAEFIK_POD --all-containers --previous --timestamps --since-time=2026-10-04T02:39:30Z +``` + +重点检查: + +- `OOMKilled`、exit code 137、liveness/readiness failure。 +- `Killing`、`Evicted`、`NodeNotReady`、`Preempted`。 +- `Configuration loaded`、provider reconnect、TLS store/default certificate 重建。 +- 10:41:32 附近是否有容器启动日志。 + +如果 Traefik 不在 `kube-system`,将命令中的 namespace 替换为实际值。 + +## 4. 第二优先级:查滚动发布和配置变更 + +```bash +kubectl -n kube-system get deploy,ds,rs -l app.kubernetes.io/name=traefik -o wide +kubectl -n kube-system rollout history deploy/traefik +kubectl -n kube-system get deploy traefik -o yaml +kubectl -n kube-system get cm,secret | grep -i traefik +``` + +若由 Helm 管理: + +```bash +helm list -A | grep -i traefik +helm history traefik -n kube-system +helm get values traefik -n kube-system -a +``` + +若由 ArgoCD 管理: + +```bash +kubectl get applications.argoproj.io -A +kubectl get applications.argoproj.io -A -o yaml | grep -n -i -C 5 traefik +kubectl get pods -n argocd -o wide +kubectl logs -n argocd -l app.kubernetes.io/name=argocd-application-controller --all-containers --timestamps --since-time=2026-10-04T02:39:30Z +``` + +同时检查 CI/CD 平台在北京时间 10:39–10:42 是否执行过 Traefik、Ingress、Service、证书或节点部署。需要记录操作者、commit、同步 revision 和开始/结束时间。 + +## 5. 第三优先级:节点是否重启或资源耗尽 + +```bash +kubectl get nodes -o wide +kubectl describe nodes +kubectl get events -A --sort-by=.metadata.creationTimestamp +kubectl get events -A --field-selector type=Warning --sort-by=.metadata.creationTimestamp +``` + +在承载 Traefik 的节点执行: + +```bash +uptime -s +last -x | head -30 +sudo journalctl --list-boots +sudo journalctl --since '2026-10-04 10:39:30' --until '2026-10-04 10:42:30' -u k3s -u k3s-agent -u kubelet -u containerd --no-pager +sudo journalctl -k --since '2026-10-04 10:39:30' --until '2026-10-04 10:42:30' --no-pager +sudo dmesg -T | grep -Ei 'oom|killed process|memory cgroup|conntrack|nf_conntrack|link.*down|reset|I/O error' +``` + +重点判断: + +- 节点是否在 10:41 左右重启。 +- 内核是否 OOM kill Traefik、containerd 或 k3s。 +- 磁盘是否满、只读或发生 I/O error。 +- 网卡是否 link down、驱动 reset。 +- kubelet 是否因 liveness probe 杀掉 Traefik。 + +## 6. 第四优先级:Service 与 Endpoint 是否短暂清空 + +```bash +kubectl get svc,endpoints,endpointslices -A | grep -Ei 'traefik|im-server' +kubectl -n kube-system describe svc traefik +kubectl -n kube-system get endpoints traefik -o yaml +kubectl -n kube-system get endpointslices -l kubernetes.io/service-name=traefik -o yaml + +kubectl -n im-server-system get pod,svc,endpoints,endpointslices -o wide +kubectl -n im-server-system describe svc im-server +kubectl -n im-server-system get endpoints im-server -o yaml +kubectl -n im-server-system get endpointslices -l kubernetes.io/service-name=im-server -o yaml +``` + +检查 10:40–10:41 是否发生: + +- Traefik Service 没有可用 endpoint。 +- `im-server` 三个 Pod 同时 NotReady,导致上游 503。 +- selector、port、targetPort 或 Ingress backend 被 ArgoCD/Helm 临时改写。 +- StatefulSet 滚动时 readiness 配置错误,所有 endpoint 被同时摘除。 + +## 7. 第五优先级:连接数和 conntrack + +在入口节点执行: + +```bash +sudo ss -lntp | grep -E ':443|:6443' +sudo ss -s +sudo sysctl net.netfilter.nf_conntrack_count net.netfilter.nf_conntrack_max +sudo conntrack -S 2>/dev/null || true +sudo nstat -az | grep -Ei 'ListenDrops|ListenOverflows|RetransSegs|InErrors|OutDiscards' +sudo ip -s link +``` + +如果有节点监控,导出 10:35–10:45 的: + +- CPU usage、load、CPU throttling。 +- 内存、OOM、working set。 +- conntrack 使用率。 +- TCP listen overflow、reset、retransmit。 +- 网卡吞吐、drop、error。 +- Traefik active connection、open connection、5xx、upstream duration。 + +conntrack 达到 `nf_conntrack_max` 通常更偏向 timeout/drop;本轮观察到短时间 `connection refused`,因此还应优先确认 443 监听进程是否消失或入口规则是否被重建。 + +## 8. im-server 同期状态 + +```bash +kubectl -n im-server-system get pods -o wide +kubectl -n im-server-system get sts im-server -o yaml +kubectl -n im-server-system describe sts im-server + +for pod in $(kubectl -n im-server-system get pods -l app=im-server -o name); do + kubectl -n im-server-system logs "$pod" --all-containers --timestamps --since-time=2026-10-04T02:39:30Z > "${pod##*/}.log" + kubectl -n im-server-system logs "$pod" --all-containers --previous --timestamps --since-time=2026-10-04T02:39:30Z > "${pod##*/}.previous.log" 2>&1 || true +done +``` + +如果 `app=im-server` 标签不匹配,先执行 `kubectl -n im-server-system get pods --show-labels`,再替换 selector。 + +需要确认三个 im-server Pod 的: + +- `startTime` 和 `restartCount`。 +- readiness/liveness failure。 +- 10:40 左右是否仍持续处理 Kafka、cluster RPC 和 WS。 +- 是否有 `too many open files`、OOM、accept error、DNS error、MySQL/Kafka timeout。 + +## 9. Kubernetes API 访问方式 + +从当前调试机访问三个源 IP 的 443 均正常。运维已确认 `216.236.31.189:6443` 只允许集群网络访问,因此外部连接超时符合既定安全策略,也与 VPN/TUN 无关。 + +运维应检查控制面节点: + +```bash +sudo ss -lntp | grep 6443 +sudo nft list ruleset | grep -n -C 3 6443 +sudo iptables -S | grep 6443 +sudo iptables -t nat -S | grep 6443 +``` + +后续排查采用以下方式之一: + +1. 让排查命令直接在控制面节点运行并回传结果包。 +2. 如确需远程调试,为固定运维出口 IP 临时增加 6443 allowlist,完成后撤销。 +3. 通过堡垒机/VPN 进入控制面网络。 + +不要为了调试把 6443 对 `0.0.0.0/0` 永久开放。 + +## 10. 运维需要回传的结果 + +至少回传以下内容: + +1. Traefik Pod YAML、describe、当前日志和 previous 日志。 +2. Traefik Deployment/DaemonSet、ReplicaSet 和 rollout history。 +3. 10:39:30–10:42:30 的 k3s/kubelet/containerd/kernel journal。 +4. 全集群 Warning Event、节点 describe。 +5. Traefik 和 im-server 的 Service、EndpointSlice、Ingress YAML。 +6. ArgoCD/Helm/CI 在故障窗口的发布历史。 +7. 入口节点 CPU、内存、conntrack、TCP overflow/retransmit 和网卡 drop。 + +拿到这些材料后,按照以下优先级定责: + +1. Traefik 容器或节点在 10:41:32 重启。 +2. ArgoCD/Helm/CI 触发 Traefik 滚动或配置重建。 +3. Traefik/im-server endpoint 短暂清空。 +4. OOM、liveness、conntrack、监听队列或节点网络故障。 +5. 其他上游负载均衡或云网络事件。 diff --git a/docs/test/IM-group2k-r11-双机群聊复测分析-20261004.md b/docs/test/IM-group2k-r11-双机群聊复测分析-20261004.md new file mode 100644 index 0000000..5cf66dd --- /dev/null +++ b/docs/test/IM-group2k-r11-双机群聊复测分析-20261004.md @@ -0,0 +1,161 @@ +# GROUP-2000 R11 双机群聊复测分析 + +## 1. 结论 + +`group2k-r11-20261004-01` 判定为 **失败且不能作为稳定容量结论**。 + +本轮确认了 R10 后的群消息共享序列化优化已经生效,正常运行阶段的实时到达率明显高于 R10;但压测末段发生了约 1 分钟的公网入口/上游整体不可用,2000 个连接几乎同时断开。与此同时,Kafka 群消息持久化链路仅落库 1165 条,662 条服务端已确认或已观测消息未落库,暴露出批消费可靠性缺陷。 + +必须先修复 Kafka 批消费和查清入口整体中断,再重复相同参数。当前不能把 93.83% 到达率当作 2000 人容量通过,也不能继续直接提高压力。 + +## 2. 核心结果 + +| 指标 | R11 结果 | 判定 | +| --- | ---: | --- | +| WS 就绪 | 2000/2000 | 通过 | +| A/B 实际起跑差 | 约 290ms | 通过 | +| 发送尝试 | 2000 | A/B 各 1000 | +| 最终明确 ACK | 1718 | 85.90% | +| 发送结果未知 | 282 | 失败 | +| ACK P95 | 58.37s | 失败 | +| 期望实时投递 | 3,654,000 | 按 1827 条服务端确认/回查消息计算 | +| 实际实时投递 | 3,428,697 | 到达率 93.83% | +| 实时缺失 | 225,303 | 6.17% | +| 数据库核验 | 1165/1827 | 缺失 662 条 | +| 重复 / 乱序 | 0 / 0 | 已收到部分正确 | +| WS 断连 | 2036 | 失败,包含重连后的再次断开 | + +R10 的实时到达率为 49.86%,R11 提升到 93.83%,说明共享序列化方向有效;但 R11 同时出现了全局入口故障和持久化缺失,两个结果的运行条件不同,不能据此计算严谨的容量提升比例。 + +## 3. A/B 分机结果 + +| 指标 | 机器 A | 机器 B | +| --- | ---: | ---: | +| 就绪连接 | 1000 | 1000 | +| 发送尝试 | 1000 | 1000 | +| 最终观测 ACK | 919 | 799 | +| 结果未知 | 81 | 201 | +| 收到群消息 | 1,816,953 | 1,611,744 | +| 断连 | 1005 | 1031 | +| 主要断连原因 | abnormal close 996 | abnormal close 653、reset 378 | + +B 的网络表现仍弱于 A,但 A 也几乎全量断开,因此本轮不能归因于单独一台压测机。 + +## 4. 故障时间线 + +时间均为北京时间 2026-10-04: + +- 10:35:36:A/B 同步开始,2000 个连接全部就绪。 +- 10:35:44 起:公网 `/metrics` 出现高延迟和多次 10s 超时,表明服务在正式断开前已经出现调度或网络拥塞。 +- 10:40:06、10:40:12:`/metrics` 返回 HTTP 521。 +- 10:40:16 起:A 机对三个直连源 IP 的 443 均收到 `connection refused`,随后登录出现 500、WS 握手出现 503。 +- 10:40:17:A 的就绪连接从 1000 降到 8,约 992 个连接集中断开;B 同期发生同类大规模断开。 +- 10:40:48–10:41:03:公网入口持续返回 503。 +- 10:41:09 后:入口恢复,客户端自动重连;A 约在 10:43:37 恢复到 1000 个连接。 + +直连源 IP 同时拒绝 443,且公网出现 521/503,这不是 Cloudflare DNS 或压测机代理造成的普通客户端故障。采样期间 Tinode cluster 指标仍为 2/2 live peers,没有证据表明原生 cluster 先失联。 + +2026-10-04 11:31–11:32 重新探测时,三个源 IP 的 443 均已恢复并可通过 `api.118im.com` Host/SNI 返回健康检查 200。三个 IP 返回的是同一张 `TRAEFIK DEFAULT CERT`,SHA-256 指纹均为 `7C:9E:00:6F:56:D6:C9:87:44:62:7D:26:93:D8:92:51:F8:DA:43:66:61:DB:8B:F9:1F:47:17:C8:93:13:C4:8C`,证书 `notBefore` 为 **2026-10-04 10:41:32**。该时间与 R11 的 521/503 和源站拒绝连接恢复窗口精确重合,是 Traefik/入口组件在故障期发生重启、重建或重新初始化的强证据。 + +目前可以把故障范围收敛到 Traefik/入口层,但仅凭默认证书时间仍不能区分 Traefik Pod 重启、Deployment 滚动、节点重启、配置重载或入口服务重建。 + +运维已确认 Kubernetes API `216.236.31.189:6443` 按安全策略不对公网开放,只允许集群网络访问;当前调试机超时属于预期行为,不是本轮故障的一部分。Pod Event、Ingress controller 日志和节点事件必须由运维从控制面节点或集群内采集。在这些证据回传前,仍不把某一个基础设施组件写成唯一根因。 + +## 5. 共享序列化与实时链路 + +三个 Pod 的 `im_topic_shared_serialization_total` 在采集窗口分别增加约 5392、6664、6831,证明新快路已实际执行。 + +按采集窗口增量估算: + +| 阶段 | 结果 | +| --- | --- | +| master Topic broadcast P95 | 不超过 5ms | +| proxy-0 Topic broadcast P95 | 不超过 5ms | +| proxy-1 Topic broadcast P95 | 不超过 10ms | +| master 到 peer-0 的 multiplex 排队 P95 | 不超过 100ms | +| master 到 peer-1 的 multiplex 排队 P95 | 不超过 250ms | +| WS read-dispatch P95 | 三个 Pod 均不超过 50ms | + +Topic 广播本身已不再呈现分钟级长尾,说明“同一群消息对每个 WS 重复 JSON 序列化”得到明显缓解。当前长尾更多出现在 multiplex 排队、socket/入口可用性以及故障后的重连恢复阶段。WS read-dispatch 仍有少量超过 5s 的样本,三个 Pod 分别约 13、10、18 次,需要保留观察,但不是本轮全量断开的充分解释。 + +## 6. Kafka 与数据库异常 + +### 6.1 对账证据 + +- 1827 条服务端确认或历史回查消息中,数据库精确找到 1165 条,缺失 662 条。 +- `im_kafka_message_persist_total{kind="group",result="batch_ok"}` 观测上限停在 1165,此后不再增长。该 counter 没有 `pod` 标签,公网采样又会随机落到不同 Pod,因此不能直接把它当作集群总数;这里只作为持久化停止推进的旁证。 +- 缺失消息全部来自第二轮:A 缺 339 条,序号 0085–0423;B 缺 323 条,序号 0085–0414。A 是完整连续区间,B 仅有少量间隙,不符合随机单条 MySQL 写失败的形态。 +- 采样结束时 group persist 的 lag 仍显示 0,但 `im_kafka_backlog_oldest_age_seconds` 在一个 Pod 上达到约 1082s。二者互相矛盾,现有 lag 指标不能作为“已消费完成”的依据。 +- 压测结束约 30 分钟后再次直连 MySQL 核验,结果仍为 1165/1827,缺失 662、错配 0、重复 0、额外消息 0。缺失没有后台追平,不能解释为普通消费延迟。 + +### 6.2 已确认的代码风险一:部分批次被丢弃 + +`fetchKafkaMessageBatch` 先连续调用 `FetchMessage` 组装批次。如果已经抓到若干消息,后续抓取返回非 `DeadlineExceeded` 错误,函数直接返回 `nil, err`,已经抓到的部分消息不会交给 handler,也不会立即提交。 + +Kafka reader 的内部读取位置已经前移。恢复后若继续抓取并提交更高 offset,之前被丢弃的消息可能随高 offset 一起被越过。这可以直接造成“生产成功、最终 lag 为 0、数据库却缺少一段连续消息”。 + +### 6.3 已确认的代码风险二:批量幂等 claim 可能活锁 + +`handleKafkaMessagePersistBatch` 在真正批量落库前逐条执行 `BeginKafkaConsume`。如果批次中途发生 Redis/基础设施错误,前面已经 claim 的消息不会释放;外层重试从批首重新开始,又会遇到 `processing` 状态。不同 claim 的过期时刻略有差异时,重试还可能反复续上前面的 claim,长期无法走到后面的消息。 + +这能解释 oldest age 长时间增长且持久化计数停止。当前“失败不提交 offset”的修复方向正确,但还没有覆盖“抓取半批失败”和“准备半批失败”两个边界。 + +### 6.4 lag 指标口径不可靠 + +当前指标直接读取 `kafka-go Reader.Stats().Lag`,同时在每次批处理结束后把 oldest age 清零。consumer group 模式下,该 lag 不是可靠的已提交 offset 差值;消息被 reader 抓取但尚未持久化时,也可能显示 0。必须改为按 partition 查询 high watermark 与 committed offset,并分别暴露 fetched、processed、committed offset。 + +## 7. 优先改进项 + +### P0:Kafka 持久化可靠性 + +1. `fetchKafkaMessageBatch` 在抓到部分消息后发生可恢复错误时,应返回已抓取批次供 handler 处理;只有一条都没抓到时才返回 fetch error。 +2. 批量准备阶段不能留下半批 claim。可先完成无副作用的解码与校验,再逐条 claim;claim 冲突时按消息拆分处理,不能让整个批次从头活锁。 +3. offset 只允许在该 partition 对应消息全部持久化成功后提交;增加 fetched/processed/committed offset 和 commit failure 指标。 +4. 增加回归测试:半批 fetch 后网络错误、准备第 N 条失败、Redis 短暂不可用、处理成功但 commit 失败、Pod 在 handler 中重启。 +5. 修复后先执行 2000 条“只验证 Kafka/MySQL”的持久化专项,要求 DB 2000/2000、lag/offset 对账一致,再恢复大群实时压测。 + +### P0:入口整体中断 + +1. 从 Ingress controller、Service endpoint、入口节点和云负载均衡拉取 10:40:00–10:41:10 的日志与事件。 +2. 核对是否发生 Ingress reload、endpoint 短暂清空、节点 conntrack/端口耗尽、进程监听中断、liveness 误杀或网络策略更新。 +3. 增加入口黑盒探针:Cloudflare 域名、源站 IP、Service、Pod 四层同时采样 TCP connect、TLS handshake、HTTP status 和耗时。 +4. 把“源站三个 IP 同时 connection refused”设为基础设施门禁,发生时本轮自动标记无效并保留现场。 + +### P1:实时链路 + +1. 保留共享序列化实现;从本轮数据看无需回退。 +2. 继续降低 master-to-proxy multiplex 排队,优先考虑兼容发布的有界批量 RPC 或单写者批发送。 +3. 补采 Pod CPU throttling、Go scheduler、GC、网卡 retransmit、Ingress upstream reset,解决 `/metrics` 本身在高压阶段失去可观测性的问题。 + +## 8. 下一轮顺序 + +1. 修复 Kafka 两个批消费边界并完成单元/故障注入测试。 +2. 运行持久化专项,确认 2000/2000 精确落库。 +3. 恢复 Kubernetes 与 Ingress 现场采集能力,查清 R11 的入口中断。 +4. 使用 R11 完全相同参数执行 R12,要求连续两轮无入口故障、无 outcome unknown、DB 2000/2000。 +5. 通过后再判断 2000 人容量;不要在问题未清零前提高并发。 + +## 9. 产物 + +- 结果目录:`loadtest/im-pressure/results/group2k-r11-20261004-01/` +- 汇总:`report.json` +- 数据库核验:`db-verification.json` +- A/B 明细:`agent-a-summary.json`、`agent-b-summary.json` +- 协调器台账:`coordinator.json` +- 指标:`metrics.jsonl` +- 被测代码:`b05e8f6 perf(group): reduce websocket fanout serialization` + +## 10. 分析后已实施修复 + +已完成以下 Kafka 持久化修复,待发版后先执行持久化专项,再进行 R12: + +1. 批量抓取在取得部分消息后遇到 broker/网络错误时,不再丢弃已抓消息;消费者会先处理并提交这部分消息,同时保留错误日志。 +2. 批准备过程中后续消息 claim 失败时,先持久化并完成前面已经 claim 的消息,再将准备错误交给外层重试,避免整批 processing claim 活锁。 +3. 新增半批 fetch error、首次 fetch error、部分 claim 后准备失败、刷盘与准备同时失败等回归测试。 + +验证结果: + +- Kafka 定向单元测试通过。 +- `go test ./server ./server/store/... ./loadtest/im-pressure` 通过。 +- Kafka 定向 `go test -race` 通过。 +- `go vet` 仍报告 `server/internal_cultivate_test.go` 中既有的 `sync.Map` 锁值复制问题,与本次改动无关。 diff --git a/server/kafka_message_persist.go b/server/kafka_message_persist.go index b6ae287..fe424cd 100644 --- a/server/kafka_message_persist.go +++ b/server/kafka_message_persist.go @@ -161,11 +161,26 @@ type kafkaMessagePersistItem struct { payload kafkaMessagePersistPayload } +type kafkaMessagePersistPreparer func(context.Context, kafka.Message, string) (*kafkaMessagePersistItem, bool, error) +type kafkaMessagePersistGroupsWriter func(context.Context, map[string][]*kafkaMessagePersistItem) error + func handleKafkaMessagePersistBatch(ctx context.Context, messages []kafka.Message, sourceTopicName string) error { + return processKafkaMessagePersistBatch(ctx, messages, sourceTopicName, + prepareKafkaMessagePersistItem, persistKafkaMessagePersistGroups) +} + +func processKafkaMessagePersistBatch(ctx context.Context, messages []kafka.Message, sourceTopicName string, + prepare kafkaMessagePersistPreparer, persist kafkaMessagePersistGroupsWriter) error { groups := make(map[string][]*kafkaMessagePersistItem) for _, message := range messages { - item, terminal, err := prepareKafkaMessagePersistItem(ctx, message, sourceTopicName) + item, terminal, err := prepare(ctx, message, sourceTopicName) if err != nil { + // Preparing an item acquires its idempotency claim. If a later item + // fails, finish all earlier claimed items before retrying the batch; + // otherwise retries can keep colliding with those processing claims. + if flushErr := persist(ctx, groups); flushErr != nil { + return fmt.Errorf("persist claimed Kafka messages after prepare failure: %w (prepare error: %v)", flushErr, err) + } return err } if terminal { @@ -177,7 +192,14 @@ func handleKafkaMessagePersistBatch(ctx context.Context, messages []kafka.Messag } groups[key] = append(groups[key], item) } + return persist(ctx, groups) +} + +func persistKafkaMessagePersistGroups(ctx context.Context, groups map[string][]*kafkaMessagePersistItem) error { for _, items := range groups { + if len(items) == 0 { + continue + } kind := items[0].payload.MessageKind if kind == "" { kind = "p2p" diff --git a/server/kafka_runtime.go b/server/kafka_runtime.go index 6ed60ec..8277fe8 100644 --- a/server/kafka_runtime.go +++ b/server/kafka_runtime.go @@ -301,6 +301,7 @@ type kafkaMessageCommitter func(context.Context, kafka.Message) error type kafkaRetryWaiter func(context.Context, time.Duration) error type kafkaBatchHandler func(context.Context, []kafka.Message) error type kafkaBatchCommitter func(context.Context, ...kafka.Message) error +type kafkaMessageFetcher func(context.Context) (kafka.Message, error) func startKafkaConsumer(topicName string, handler kafkaMessageHandler) { startKafkaConsumerWithGroup(topicName, "", handler) @@ -389,19 +390,23 @@ func startKafkaBatchConsumer(topicName string, handler kafkaBatchHandler) { defer kafkaBus.wg.Done() defer reader.Close() for { - messages, err := fetchKafkaMessageBatch(kafkaBus.ctx, reader, kafkaBus.config.MessageBatchSize, + messages, fetchErr := fetchKafkaMessageBatch(kafkaBus.ctx, reader, kafkaBus.config.MessageBatchSize, time.Duration(kafkaBus.config.MessageBatchWait)*time.Millisecond) - if err != nil { - if errors.Is(err, context.Canceled) || errors.Is(kafkaBus.ctx.Err(), context.Canceled) { + if fetchErr != nil && len(messages) == 0 { + if errors.Is(fetchErr, context.Canceled) || errors.Is(kafkaBus.ctx.Err(), context.Canceled) { return } - logs.Err.Println("Kafka batch fetch failed:", err) + logs.Err.Println("Kafka batch fetch failed:", fetchErr) continue } + if fetchErr != nil { + logs.Warn.Printf("Kafka batch fetch interrupted; processing retained messages: topic=%s size=%d err=%v", + topic, len(messages), fetchErr) + } if len(messages) > 0 { readerMetrics.observe(messages[0].Time) } - if err = consumeKafkaMessageBatch(kafkaBus.ctx, messages, handler, reader.CommitMessages, waitKafkaRetry); err != nil { + if err := consumeKafkaMessageBatch(kafkaBus.ctx, messages, handler, reader.CommitMessages, waitKafkaRetry); err != nil { if errors.Is(err, context.Canceled) || errors.Is(kafkaBus.ctx.Err(), context.Canceled) { return } @@ -468,7 +473,11 @@ func (m *kafkaReaderMetrics) update() { } func fetchKafkaMessageBatch(ctx context.Context, reader *kafka.Reader, maxSize int, maxWait time.Duration) ([]kafka.Message, error) { - first, err := reader.FetchMessage(ctx) + return fetchKafkaMessageBatchWith(ctx, maxSize, maxWait, reader.FetchMessage) +} + +func fetchKafkaMessageBatchWith(ctx context.Context, maxSize int, maxWait time.Duration, fetch kafkaMessageFetcher) ([]kafka.Message, error) { + first, err := fetch(ctx) if err != nil { return nil, err } @@ -480,13 +489,16 @@ func fetchKafkaMessageBatch(ctx context.Context, reader *kafka.Reader, maxSize i break } fetchCtx, cancel := context.WithTimeout(ctx, remaining) - message, fetchErr := reader.FetchMessage(fetchCtx) + message, fetchErr := fetch(fetchCtx) cancel() if errors.Is(fetchErr, context.DeadlineExceeded) && ctx.Err() == nil { break } if fetchErr != nil { - return nil, fetchErr + // FetchMessage advances the reader's internal position before offsets are + // committed. Preserve a partial batch so a later higher-offset commit cannot + // skip messages already fetched into this batch. + return messages, fetchErr } messages = append(messages, message) } diff --git a/server/kafka_runtime_batch_test.go b/server/kafka_runtime_batch_test.go index e79c847..7e09491 100644 --- a/server/kafka_runtime_batch_test.go +++ b/server/kafka_runtime_batch_test.go @@ -75,6 +75,103 @@ func TestConsumeKafkaMessageBatchDoesNotCommitWhileHandlerFails(t *testing.T) { } } +func TestFetchKafkaMessageBatchWithRetainsPartialBatchOnFetchError(t *testing.T) { + fetchCalls := 0 + fetchErr := errors.New("broker connection reset") + messages, err := fetchKafkaMessageBatchWith(context.Background(), 10, time.Second, + func(context.Context) (kafka.Message, error) { + fetchCalls++ + if fetchCalls == 1 { + return kafka.Message{Partition: 2, Offset: 41}, nil + } + return kafka.Message{}, fetchErr + }) + + if !errors.Is(err, fetchErr) { + t.Fatalf("fetchKafkaMessageBatchWith() error = %v, want %v", err, fetchErr) + } + if len(messages) != 1 || messages[0].Partition != 2 || messages[0].Offset != 41 { + t.Fatalf("fetchKafkaMessageBatchWith() messages = %#v, want retained offset 41", messages) + } +} + +func TestFetchKafkaMessageBatchWithReturnsInitialFetchErrorWithoutMessages(t *testing.T) { + fetchErr := errors.New("broker unavailable") + messages, err := fetchKafkaMessageBatchWith(context.Background(), 10, time.Second, + func(context.Context) (kafka.Message, error) { + return kafka.Message{}, fetchErr + }) + + if !errors.Is(err, fetchErr) { + t.Fatalf("fetchKafkaMessageBatchWith() error = %v, want %v", err, fetchErr) + } + if len(messages) != 0 { + t.Fatalf("fetchKafkaMessageBatchWith() messages = %#v, want none", messages) + } +} + +func TestProcessKafkaMessagePersistBatchFlushesClaimsBeforePrepareRetry(t *testing.T) { + prepareErr := errors.New("redis temporarily unavailable") + prepareCalls := 0 + persistCalls := 0 + + err := processKafkaMessagePersistBatch(context.Background(), []kafka.Message{{Offset: 10}, {Offset: 11}}, "group_message_persist", + func(_ context.Context, message kafka.Message, topic string) (*kafkaMessagePersistItem, bool, error) { + prepareCalls++ + if topic != "group_message_persist" { + t.Fatalf("prepare topic = %q", topic) + } + if message.Offset == 11 { + return nil, false, prepareErr + } + return &kafkaMessagePersistItem{ + tenantID: types.TenantID(7), + payload: kafkaMessagePersistPayload{ + MessageKind: "group", + ShardMonth: "202610", + Message: types.Message{ShardMonth: "202610"}, + }, + }, false, nil + }, + func(_ context.Context, groups map[string][]*kafkaMessagePersistItem) error { + persistCalls++ + items := groups["7:202610"] + if len(items) != 1 { + t.Fatalf("persisted groups = %#v, want one claimed item", groups) + } + return nil + }) + + if !errors.Is(err, prepareErr) { + t.Fatalf("processKafkaMessagePersistBatch() error = %v, want %v", err, prepareErr) + } + if prepareCalls != 2 || persistCalls != 1 { + t.Fatalf("calls prepare=%d persist=%d, want 2/1", prepareCalls, persistCalls) + } +} + +func TestProcessKafkaMessagePersistBatchReportsFlushAndPrepareErrors(t *testing.T) { + prepareErr := errors.New("claim failed") + persistErr := errors.New("database unavailable") + prepareCalls := 0 + + err := processKafkaMessagePersistBatch(context.Background(), []kafka.Message{{Offset: 10}, {Offset: 11}}, "message_persist", + func(_ context.Context, _ kafka.Message, _ string) (*kafkaMessagePersistItem, bool, error) { + prepareCalls++ + if prepareCalls == 2 { + return nil, false, prepareErr + } + return &kafkaMessagePersistItem{tenantID: types.TenantID(7)}, false, nil + }, + func(context.Context, map[string][]*kafkaMessagePersistItem) error { + return persistErr + }) + + if !errors.Is(err, persistErr) || !strings.Contains(err.Error(), prepareErr.Error()) { + t.Fatalf("processKafkaMessagePersistBatch() error = %v, want both flush and prepare errors", err) + } +} + func TestConsumeKafkaMalformedMessageRetriesCommit(t *testing.T) { commitCalls := 0 waitCalls := 0