DGJ2 项目日志优化记录

1. 文档用途

这份文档是 DGJ2 日志治理的持续台账。以后每一次日志优化，都按同一套格式追加：

本台账遵守三个原则：

1. Kafka 消费入口保留一份完整原始消息，作为链路的“原始证据”。
2. 下游节点不重复打印完整对象，但必须保留 RequestId 和能够判断节点是否执行、执行结果是什么的最小字段。
3. 正常成功路径记录摘要；格式错误、业务异常、外部调用失败保留足够的失败原因，必要时只在异常分支输出完整上下文。

2. 当前统计口径

• 项目：DGJ2 AI 报价 / RobotInquiry。
• 当前代码分支：bugfix/20260827-log。
• 当前版本基线：1b94e4cbef（日志优化后的现有代码基线）。
• 日志查询：内网 Kibana API，索引 logstash-2026.08.27。
• 最新量级窗口：2026-08-27 16:00:00 ~ 16:15:00，东八区。
• message 的量级使用 Elasticsearch message.length() 统计，单位是字符，不等同于磁盘字节；用于同一口径的相对比较。
• 线上日志已经集中到 Kibana，本台账不依赖登录服务器直接读取线上文件。

3. 上线前后总体效果

本次发布以 2026-08-26 20:15 重启后的 20:16~20:17 作为优化后窗口，与上线前 19:59~20:00 对比。两段时间流量不完全相同，因此同时看总量和“每条 onMessage 的平均字符数”。

说明：选取的几个重点日志点合计从 45,705,732 字符下降到 341,008 字符；按 onMessage 开始 归一化后，每条消息相关日志从约 54,606 字符下降到约 590 字符。这个结果说明本次主要收益来自“去掉重复完整对象”，不是减少业务处理次数。

4. 已完成的优化台账

4.1 入口与链路日志

4.2 联系人、会话与异常日志

5. 最新未优化日志量级排序

以下是 2026-08-27 16:00~16:15 内网 robot_inquiry 日志的聚合结果。数字按 message.length() 统计，目的是决定优化优先级；“条数多”与“单条大”要分别看。

补充判断：parseNotify 和 onMessage 开始 虽然总字符数靠前，但当前已经是固定短字段；它们应继续保留作为链路节点，不应仅按总量再次删除。真正优先的是仍然打印完整业务对象的 P0/P1 日志。

6. 下一批具体落地方案

6.1 P0：setConversationRecord:生成会话记录

当前代码位于 application/Services/MoveMall/RobotInquiryBaseSer.php:2183 附近，打印的是完整 $data。其中最容易变大的字段是：

• source_content：可能是图片、音频地址或较长原始内容。
• text：用户原始文本。
• keyword：完整关键词解析结果 JSON。
• 其它联系人、服务站、会话字段：与前面节点重复。

建议改成一条摘要日志，保留：

request_id, cv_id, contact_id, sid, wxid, role,
source_type, source_content_length, text_length,
keyword_count/keyword_type, text_flag, text_flag_order_type

不要在成功 info 中打印 source_content、完整 text、完整 keyword。如果 conversationRecordModel->add() 失败，错误日志保留上述 ID 和失败原因；需要复现原始输入时，通过同一 request_id 回查入口 收到消息，而不是依赖这条数据库记录日志。

6.2 P0：searchWxList:查询到商城商品数量

当前代码位于 application/Services/MoveMall/MoveMallGoodsSer.php:1202 附近，变量 $res 是完整商品查询返回，不是“数量”。

成功路径建议只记录：

request_id, vin, page, page_size, result_code,
rows_count, category_count, car_count,
first_product_ids/top_product_codes, elapsed_ms

异常路径记录接口错误码、接口耗时、查询条件摘要；完整 $res 只在异常或临时 debug 开关打开时打印，并且要有截断上限。这样仍能判断“是否查询到商品、数量是否异常、过滤条件是否命中”，但不会把数百 KB 的商品数组每次写入日志。

本次已在 bugfix/20260827-log 完成最小修改，并抽取为公共方法 BaseSer::formatLogContext()：

• searchWxList 和 searchWxList-self 两条日志都统一处理，避免只改微仓路径而遗漏自提仓路径。
• 公共方法先将数据序列化为 JSON，再按 UTF-8 字符数限制到 500 个字符；超过上限时保留前 497 个字符并追加 ...，后续其它服务日志也可以复用。
• 日志只使用截断后的 result 字符串，业务后续仍继续使用原始 $res，不改变商品查询、过滤和返回逻辑。
• JSON 序列化失败时只记录短错误提示，不会因为日志处理影响业务流程。

当前状态：代码已发布到预发，并已通过真实消息链路验证；searchWxList 的结果上下文为 500 字符，超长时末尾为 ...。整体 15 分钟窗口的长期量级仍需在业务高峰期持续观察，单次验证结果见第 12 节。

6.3 P0：setContact:设置联系人

当前代码位于 application/Services/MoveMall/RobotInquiryBaseSer.php:221，完整 contact 是明确的大量来源，而且前后多个节点都有 contact。

建议保留：

request_id, contact_id, sid, chat_group_id,
wxid, wxname, contact_name, bind_match=true/false

不要在正常成功路径打印完整 $this->contact。联系人为空、服务站不匹配时，保留 bindWxId、回调服务站、绑定服务站、错误原因；这已经足够定位“找不到绑定客户”和“绑定站点不一致”。

6.4 P0：处理optionPrivateChat

当前代码位于 application/Services/MoveMall/RobotInquiryBaseSer.php:2098，每次直接打印完整 $this->notify，而入口已经保存完整消息。

建议保留：

request_id, msg_id, event, from_wxid, to_wxid, robot_wxid,
content_type, content_length, verify_code_flow=true

验证码校验失败保留 error；只在异常且确需复现时，通过 RequestId 回查入口原始消息。这样能判断是否进入验证码分支、处理的是哪条消息，也不会丢链路。

6.5 P1：库存、商品和排序循环日志

6.6 P1/P2：高频小日志和长尾大日志

• unlock:释放锁：释放失败必须保留；正常成功可以改为 debug 或按比例采样，仍保留获取锁失败、释放失败和耗时超阈值日志。
• formatMessage:缓存数据：保留缓存命中/未命中、key 类型、数据条数、序列号范围；不打印完整 cacheData/showData。
• processVinConversation:车型解析成功：保留 cars_count、首个车型 ID/名称、耗时；完整 cars 仅在解析异常时输出。
• RobotSegmentationService: 开始处理@提醒文本：保留文本长度、成员数量、前 N 个成员 ID；对文本设置长度上限，避免 57KB 单条日志。
• checkAndPlaceAgentOrder:根据报价记录获取最近会话信息：保留报价记录 ID、会话 ID、查询耗时；不要输出完整 SQL 和完整 conversation，SQL 异常另行记录 SQL 类型/模板标识。
• Kafka 消费循环中的 当前IP：进程启动或 IP 变化时打印一次即可。
• Kafka Local: Timed out：正常 poll 超时不是业务异常，不应每次以 error/info 打印；只统计计数，连续超时超过阈值或发生非 timeout 错误时告警。

7. “一条消息一份完整证据”的链路设计

一条消息的推荐查询顺序如下：

Kafka 收到消息（唯一完整 payload）
        |
        +--> onMessage 开始（确认进入处理，RequestId/内存信息）
        |
        +--> parseNotify（msg_id/event/from/robot 摘要）
        |
        +--> setContact（绑定微信、联系人和服务站摘要）
        |
        +--> loadConversation（cvKey、conversation、pre 会话 ID/状态）
        |
        +--> 商品查询/库存/排序（数量、ID、耗时摘要）
        |
        +--> 会话落库（记录 ID/会话 ID/内容长度/标志位）
        |
        +--> onMessage 结束 或 消息处理失败

排查时优先使用：

1. RequestId：串起一次消费处理链路。
2. msg_id：确认是不是同一条微信消息；当内部服务重新生成 RequestId 时，用它补充关联。
3. contact_id、cv_id、record_id、sid：定位联系人、会话、落库记录和服务站。
4. source_type、数量、耗时和错误原因：判断是在入口、绑定、会话、商品查询还是落库阶段出问题。

因此，减少下游完整对象不会导致无法排查，前提是入口确实保留一份完整消息，并且所有下游节点都保留稳定关联字段。绝不能把入口完整日志、格式错误完整日志和异常证据同时删掉。

8. 当前代码风险与本次日志优化无关的独立问题

以下问题不应通过“多打印日志”掩盖，需要单独立 Bug：

1. Robot.php 当前在处理消息前提交 Kafka offset；如果后续处理失败，可能已经无法重新消费。
2. onMessage 内部捕获异常后如果返回成功，外层消费者可能记录成功并提交 offset，导致“业务失败但消费成功”的状态不一致。
3. 消息处理失败 的 trace 优化只适用于明确的业务预期异常，例如“未绑定客户”；未知 PHP 异常、外部接口异常仍必须保留 trace 或错误定位信息。
4. 任何完整日志改摘要，都必须保证不改变原有业务变量和返回值；日志表达式也不能调用有副作用的方法。

9. 每次发布后的验证清单

10. 变更记录

11. 后续追加模板

12. 2026-09-10 生产搜索日志发布验证

本次验证只统计 DGJ 自身日志，不能将 VinAudit 服务端 /product/search 混入 DGJ 最大日志排名。

12.1 DGJ OfferProvider 搜索响应

• 目标入口：DGJ 调 Sale /offer/search/list 的成功响应日志；phone/offer/search/list 和其他 Provider 不在本次改动范围。
• 生产验证窗口：2026-09-10 21:10–21:25。
• 258 条请求对应 258 条响应，258 条为新摘要格式，旧的完整 data 响应为 0；code=0，ProviderErrorException、RequestTimeoutException、PHP Fatal、Uncaught 均为 0。
• 同口径上线前后字符量：2,010,924 -> 488,296；平均单条：24,228 -> 7,077；最大单条：79,652 -> 19,813；总字符量下降约 75.7%。原始业务响应仍由代码返回给调用方，摘要只用于日志。

12.2 DGJ 自身剩余日志排序

在 2026-09-10 21:55–22:10 窗口、来源限定 /data/logs/dgj/ 的统计为：

该窗口 DGJ 自身日志约 56.85M 字符。更早同口径对比显示 DGJ 总量约 2,668.96M -> 1,419.36M 字符、下降约 46.8%；providers/default 响应约下降 98.4%，AES 请求仅下降约 4.3%，因此下一优先级是 AES 请求而不是已完成的搜索响应摘要。

12.3 跨系统关联边界

DGJ、Sale、VinAudit 当前各自保留本地 RequestId；Sale 请求体可完整解析，但正常大响应日志在约 1,024 字符处截断，业务响应本身未截断。后续建议增加 Dgj-Request-Id 请求头并由下游继续透传，同时保留各系统本地 ID，先做单节点验证，不直接覆盖现有 request_id。

新增优化时直接复制下面的表格行，并补齐真实 Kibana 数据：

12. 2026-08-27 预发真实链路验证

12.1 验证方式

通过预发入口调用正常 Robot 消息接口：

POST http://dgj-staging.kzmall.cc/index.php/moveMall/RobotController/receiveMsg

调用从预发 Robot 主机发起，使用预发已绑定会话和测试 VIN；先发送 VIN 完成车型解析，再发送“VIN + 已配置品类词”，确保真正进入 searchWxList。本次未访问线上 Kibana，也未修改预发服务器配置。

12.2 代码与主机确认

12.3 业务调用与日志结果

12.4 测试过程中的独立兼容性问题

第一次人工构造报文使用了 final_from_name，而当前历史协议/代码读取的是拼写为 fina_from_name 的字段，导致测试报文在会话记录落库时出现 wxname cannot be null。修正为真实报文字段后调用成功；这属于测试报文协议兼容问题，不是日志截断改动造成的业务错误。后续构造测试报文必须复用真实网关报文字段，不要自行改写字段名。

12.5 发布后继续观察

本次是单次真实链路验证，证明功能和截断逻辑正常，但不能代替高峰期统计。下一步按相同 15 分钟窗口对比：searchWxList 总字符数、平均单条、最大单条，以及 robot_inquiry 总量；重点确认高峰期是否还有其它完整 goods、conversation、排序数组日志成为新的 P0。