👁 110 次阅读

Dify 日志页为何会漏掉同秒发送的消息

来源：https://github.com/langgenius/dify/issues/43134

现象描述

在 Dify 1.17.1（Self Hosted，Docker 部署）中，社区用户报告了一个消息丢失问题。复现步骤大致如下： 1. 创建一个只包含 Start 节点和 Answer 节点的 Chatflow 应用，发布应用并生成 API key。 2. 通过 Service API（POST /v1/chat-messages，使用同一个 conversation_id）向同一个会话快速发送消息。先发送 hi，然后在循环中依次快速发送 msg-1 到 msg-15。 3. 打开应用的 Logs 页面，进入该会话，向上滚动加载全部消息。 Logs 页面显示了 15 条问题，但 msg-5 缺失，实际渲染顺序为：

hi, msg-1, msg-2, msg-4, msg-3, msg-6, msg-8, msg-7, msg-11, msg-10, msg-9, msg-12, msg-13, msg-14, msg-15

值得注意的是，消息并非严格按照发送顺序展示，成对的消息（如 msg-3/msg-4、msg-7/msg-8）出现次序发生交换，而 msg-5 则彻底没有渲染出来。

背景原因

查询数据库可以看到，16 条消息全部存在，问题出在排序与分页边界上：

SELECT query, created_at FROM messages WHERE conversation_id = '{conversation_id}' ORDER BY created_at;

query  |     created_at
--------+---------------------
 hi     | 2026-09-28 13:24:05
 msg-1  | 2026-09-29 05:19:49
 msg-2  | 2026-09-29 05:19:52
 msg-4  | 2026-09-29 05:19:53
 msg-3  | 2026-09-29 05:19:53
 msg-5  | 2026-09-29 05:19:54
 msg-6  | 2026-09-29 05:19:54
 msg-8  | 2026-09-29 05:19:55
 msg-7  | 2026-09-29 05:19:55
 msg-11 | 2026-09-29 05:19:56
 msg-10 | 2026-09-29 05:19:56
 msg-9  | 2026-09-29 05:19:56
 msg-13 | 2026-09-29 05:19:57
 msg-12 | 2026-09-29 05:19:57
 msg-15 | 2026-09-29 05:19:58
 msg-14 | 2026-09-29 05:19:58

从数据可以看到，许多消息共享同一个 created_at。例如 msg-3 与 msg-4 同为 05:19:53，msg-5 与 msg-6 同为 05:19:54，msg-7 与 msg-8 同为 05:19:55，msg-9、msg-10、msg-11 三条同为 05:19:56。 issue 正文给出的根因分析指出：

• 在 PostgreSQL 上，messages.created_at 默认值为 CURRENT_TIMESTAMP(0)，即只有秒级精度。同一秒内发送的消息会拿到完全相同的 created_at。
• Logs 页面通过 GET /console/api/apps/{app_id}/chat-messages 加载消息，limit=10。加载更早的消息时，会把当前已加载消息中最旧的一条作为 first_id 传入。
• api/controllers/console/app/message.py 中的 _list_chat_messages 只按 created_at 排序（1.17.1 中为 L471、L478）。当多条记录时间戳相同时，基于单一时间字段做游标分页会丢失记录。

社区用户 chenhz01 在讨论中进一步确认了同一根因： > Same root cause as the run/variables pagination bugs: the Logs query orders by created_at and uses a boundary that assumes unique timestamps, so when several messages share the same created_at (your msg-3/4/5/6 all at 05:19:5x) the keyset boundary drops a row and msg-5 never renders. The fix is a deterministic tiebreaker on (created_at, id).

排查或量化方法

判断该问题是否与时间戳精度相关，可以通过以下路径量化：

• 直接查询数据库，按 created_at 排序取出同一会话的全部消息，确认数据库中记录是否完整。本例中 16 条全部存在，说明不是写入丢失。
• 统计同一会话内 created_at 的重复分布。当存在多组重复时间戳时，单调时间字段已无法唯一确定顺序。
• 对比 Logs 页面渲染出的消息 ID 列表与数据库返回的完整列表，找出缺失项。本例缺失的正是处于同一秒内、且相邻的多条记录之一。
• 由于 Console API 使用 first_id 作为翻页游标，可以检查被选作 first_id 的那条消息是否与其它消息共享同一 created_at。

完整解决方案

社区在讨论中提交了修复分支并推进评审。核心思路是把排序与游标条件从单一 created_at 改为 (created_at, id) 复合键，使排序确定化。 JHC56 在 2026-09-29 描述了其提交的方案： > #43146 is ready for review. > Updates: > – One shared keyset condition (_older_than) is used for both the page query and the has_more check. > – The regression test pages through 5 messages with the same created_at, with limit=1 and limit=2. > – The test checks the exact order, has_more on each page, and that no message is skipped. > – The test fails before the fix and passes after. 要点归纳：

• 分页查询与 has_more 判定共用同一个 keyset 条件（_older_than），避免两处逻辑不一致导致的边界错位。
• 回归测试构造 5 条 created_at 相同的消息，分别以 limit=1 和 limit=2 翻页。
• 断言覆盖精确顺序、每页的 has_more、以及消息无遗漏。
• 该测试在修复前失败、修复后通过，具备回归价值。

同一讨论中的另一条 PR（#43138）最初只校验消息是否全部到达，未校验顺序。JHC56 指出： > @charan-rathore I noticed the test in #43138 only checks that every message arrives. If I’m not mistaken, the test does not check the order of the messages yet. Would it be worth also checking the order, since a stable order is part of this f charan-rathore 随后补充了顺序断言： > Good catch – completeness alone doesn’t pin the order. Added an assertion on #43138 that pages must return IDs in exact descending (created_at, id) order across and within pages, at limits 1 and 2. Thanks for the sharp read. chenhz01 也提供了参考实现思路，并强调用 (created_at, id) 作为确定性 tiebreaker： > The fix is a deterministic tiebreaker on (created_at, id). Reference impl (swap the rows list for your DB query): JHC56 回应确认已采用数据库层查询内的 (created_at, id) keyset 方案并包含回归测试，同时说明无需额外的 SQLAlchemy 查询。 截至 2026-09-29 至 2026-09-30 的讨论，issue #43134 状态仍为 open，标签为 🐞 bug、review: medium。修复 PR #43146 已进入评审阶段（”ready for review”），但讨论中并未出现维护者确认已合并或已随某个版本发布的信息，因此本问题的官方修复尚未落到发布版本。

参数或对比表格

维度	修复前	修复后（PR #43146 方案）
排序字段	仅 created_at	(created_at, id)
翻页游标	以最旧消息作为 first_id，按 created_at 比较	共享 keyset 条件 _older_than，按 (created_at, id) 比较
has_more 判定	与分页查询可能不一致	与分页查询共用同一条件
同秒消息顺序	不稳定，可能出现交换	按 id 作为 tiebreaker 确定顺序
同秒消息完整性	可能丢失记录（如 msg-5）	回归测试覆盖 5 条同 created_at 消息，无遗漏
回归测试断言	仅校验消息是否全部到达	校验精确降序 (created_at, id) 顺序、has_more、无遗漏

常见错误排查

• 误判为写入失败：先在数据库按 conversation_id 直接查询，确认消息是否真实落库。本例中 16 条全部存在，问题在读取与分页环节，而非写入。
• 只检查总条数不检查顺序：只统计页面渲染出多少条，可能漏掉顺序错乱或缺失。应对照数据库返回的 ID 列表逐条比对。
• 只做一个 limit 值的测试：分页边界错误往往只在特定 limit 下暴露。讨论中的回归测试同时使用 limit=1 与 limit=2，值得借鉴。
• 忽略 has_more 与查询条件的一致性：has_more 若与分页查询使用不同的边界条件，会诱导前端停止翻页或提前翻页，造成尾部消息不可见。
• 把时间戳精度问题当成前端渲染问题：PostgreSQL 上 created_at 为 CURRENT_TIMESTAMP(0)，秒级精度本身不是 bug，但它要求分页必须引入确定性二级排序键。

实践建议

• 任何基于时间戳的游标分页，只要时间字段不是唯一值，就应引入 (timestamp, id) 复合排序键，保证顺序确定、可复现。
• 分页查询与 has_more 判定应复用同一个边界条件函数，避免两处实现漂移。
• 回归测试应同时断言完整性、顺序和分页标志，并覆盖存在重复时间戳的边界数据集。
• 对时间精度较低（如秒级或分钟级）的时间字段，默认视为不可作为唯一排序依据。
• 在 issue 讨论中，社区推荐的方式是在数据库查询层完成 keyset 过滤，而不是在应用层用额外查询绕开边界问题。

FAQ

问题一：为什么数据库里数据完整，Logs 页面却少了 msg-5？ 数据库查询显示 16 条消息全部存在，缺失发生在分页读取阶段。_list_chat_messages 仅按 created_at 排序，当多条消息共享同一时间戳时，基于单一时间字段的游标条件会跳过部分记录。 问题二：msg-3 和 msg-4 的顺序为何会颠倒？ 由于两条消息 created_at 完全相同（均为 05:19:53），仅按 created_at 排序无法确定稳定顺序。加入 id 作为 tiebreaker 后顺序才会确定。 问题三：修复方案是否已合并并随版本发布？ 截至讨论记录，issue #43134 仍为 open，修复 PR #43146 处于 “ready for review” 状态。讨论中未出现维护者确认已合并或已发布的信息，因此不能视为已随某个版本发布。如需确认合并状态，可通过 GitHub API 查询对应 PR 的合并记录。 问题四：为什么同一根因还影响其它分页接口？ 据 issue 讨论，chenhz01 指出该问题与 run/variables 分页 bug 属同一根因，均因查询按 created_at 排序、且边界条件假定时间戳唯一所致。相关讨论中还提到 #43084、#43087 涉及 conversation variables API。 问题五：回归测试只验证消息是否全部到达，够吗？ 不够。讨论中 charan-rathore 明确承认”completeness alone doesn’t pin the order”，随后补充了在 limit=1 与 limit=2 下断言分页必须严格返回降序 (created_at, id) 顺序的断言。完整性、顺序与 has_more 需要一起校验。