EMQX5.8.4开源 dashboard当前连接数高于on_client_authenticate/on_client_connected日志统计值

EMQX 错误报告
,
1

环境

  • EMQX 版本：v5.8.4开源版
  • 操作系统版本：k8s 部署 2*core
  • 资源：2C*2

重现此问题的步骤

压测目标：5w MQTT TLS 连接
压测工具：emqtt-bench
连接速率：1000/s 建连速率
关注的 hook：

  • on_client_authenticate
  • on_client_connected
  • on_client_disconnected

统计方式：

  • on_client_authenticate：通过 hook 日志统计次数
  • on_client_connected：通过 hook 日志统计次数
  • on_client_disconnected：通过 hook 日志统计次数
  • 连接数：通过 Dashboard 查看当前在线连接数

下面测试的hook全部成功没有失败的

一共测试了3次：

  1. on_client_authenticate钩子日志数量：41254
    on_client_connected钩子日志数量：41051
    on_client_disconnected钩子日志数量：18
    dashboard当前连接数: 49988
    当前连接数 49988 明显高于 on_client_connected = 41051
  2. on_client_authenticate钩子日志数量：40770
    on_client_connected钩子日志数量：40554
    on_client_disconnected钩子日志数量：1389
    dashboard在线连接数: 45861
    当前连接数 45861 高于 on_client_connected = 40554
  3. on_client_authenticate钩子日志数量：40868
    on_client_connected钩子日志数量：40722
    on_client_disconnected钩子日志数量：1196
    dashboard在线连接数: 48188
    当前连接数 48188 高于 on_client_connected = 40722

预期行为

在hook全部执行成功的情况下，且日志只会打印一次
我认为压测期间，dashboard的当前连接数应该小于等于on_client_connected日志数量

实际行为

我目前的理解是：

  1. on_client_authenticate 和 on_client_connected 不完全相等是可以理解的
    因为可能存在客户端在 authenticate 之后、connected 之前断开连接的情况。
  2. 但如果 Dashboard 当前连接数高于 on_client_connected 统计值，从时序上看就比较难理解。
    因为一个当前仍在线的连接，理论上应该已经进入过 on_client_connected。
  3. 这个现象只在 1000/s 高建连速率下稳定出现，而在 200/s、500/s 下没有出现。
2

先别把 Dashboard 里的“当前连接数”和 on_client_connected 的日志条数按 1:1 对。
/api/v5/stats 里有两个不同字段：

  • connections.count: current connections
  • live_connections.count: current live connections
    你这个现象更像是拿了 connections.count 去对比 hook 事件数。文档把 live_connections.count 单独拆出来，说明“当前连接”不等价于已经走完 on_client_connected 的连接。1000/s + TLS 下，建连窗口被拉长时，统计口径差异会被放大。
    先按这几个点核一下：
  1. 同一时刻抓 /api/v5/stats，把 connections.count 和 live_connections.count 一起看。
  2. hook 日志确认是全量汇总的，别只看单个 EMQX Pod / 单个 exhook 实例；K8s 多副本时很容易少算。
  3. 再比较 live_connections.count 和 on_client_connected - on_client_disconnected，这个值才更接近你想验证的“当前在线 MQTT 连接”。
    可以直接抓一份原始数据：
curl -u <app_id>:<app_secret> http://<host>:18083/api/v5/stats | jq '.["connections.count"], .["live_connections.count"]'

如果 live_connections.count 仍然明显高于 hook 统计，再补这几项：

  • EMQX 是多 Pod，hook 日志怎么汇总的
  • hook 是 ExHook 还是自定义插件，日志打印点在回调入口还是回调返回之后
  • 问题时段的 /api/v5/stats 原始返回和 emqx.log
    这些信息齐了，基本就能判断是统计口径问题，还是 hook 路径里真有漏记。
3
  • EMQX 是多 Pod，hook 日志怎么汇总的
    回答：aliyun SLS服务采集所有pod的日志目录下的所有日志文件，这个地方应该不存在漏日志的情况。
  • hook 是 ExHook 还是自定义插件，日志打印点在回调入口还是回调返回之后
    回答：hook是插件不是exhook形式, 日志是打印在回调返回之前，是连接鉴权逻辑执行完毕，最终返回结果之前。on_client_connected是在执行完成时打印的日志
  • 问题时段的 /api/v5/stats 原始返回和 emqx.log
[
    {
        "node": "emqx@emqx-core-6fc554b486-1.emqx-headless.emqx-core-debug.svc.cluster.local",
        "subscribers.max": 149795,
        "subscribers.count": 144279,
        "subscriptions.max": 149795,
        "subscriptions.count": 144279,
        "suboptions.max": 149795,
        "suboptions.count": 144279,
        "channels.count": 24048,
        "channels.max": 24967,
        "sessions.count": 24048,
        "sessions.max": 24967,
        "connections.count": 24048,
        "connections.max": 24967,
        "live_connections.count": 24047,
        "live_connections.max": 24967,
        "cluster_sessions.count": 48083,
        "cluster_sessions.max": 49989,
        "topics.max": 299917,
        "topics.count": 288485,
        "subscriptions.shared.max": 0,
        "subscriptions.shared.count": 0,
        "retained.count": 10,
        "retained.max": 10,
        "delayed.max": 0,
        "delayed.count": 0
    },
    {
        "node": "emqx@emqx-core-6fc554b486-0.emqx-headless.emqx-core-debug.svc.cluster.local",
        "subscribers.max": 150122,
        "subscribers.count": 144206,
        "subscriptions.max": 150122,
        "subscriptions.count": 144206,
        "suboptions.max": 150122,
        "suboptions.count": 144206,
        "channels.count": 24035,
        "channels.max": 25022,
        "sessions.count": 24035,
        "sessions.max": 25022,
        "connections.count": 24035,
        "connections.max": 25022,
        "live_connections.count": 24035,
        "live_connections.max": 25022,
        "cluster_sessions.count": 48082,
        "cluster_sessions.max": 49989,
        "topics.max": 299917,
        "topics.count": 288479,
        "subscriptions.shared.max": 0,
        "subscriptions.shared.count": 0,
        "retained.count": 10,
        "retained.max": 10,
        "delayed.max": 0,
        "delayed.count": 0
    }
]

这个是最新一次测试的数据，同是on_client_authenticate日志数量为：40945, on_client_connected日志数量为：40777
两个core节点 live_connections.count总数还是高于hook的统计

4

从你贴的 /api/v5/stats 看，Broker 自己的连接统计基本是自洽的，先别把锅丢给 Dashboard。两个 core 节点的 live_connections.count 分别是 24047 和 24035，合起来 48082，和每个节点看到的 cluster_sessions.count = 48082/48083 基本对上。按文档定义，live_connections.count 是“当前在线连接数”，client.connected / client.connected hook 才是“成功建立的连接事件数/回调”。
现在真正冲突的是：Broker 统计在线 48082，但你插件里 on_client_connected 只记了 40777。从现象看，这更像是插件侧计数漏了，不是 Dashboard 多算。
先直接对内置指标，不要再拿文本日志条数做基准：

curl -su <app_id>:<app_secret> 'http://<host>:18083/api/v5/metrics?aggregate=true' \
| jq '."client.connected", ."client.disconnected", ."client.authenticate", ."session.created", ."session.resumed", ."session.takenover"'
curl -su <app_id>:<app_secret> 'http://<host>:18083/api/v5/stats' \
| jq '[.[]."live_connections.count"] | add'

看这两组数据怎么对：

  • 如果 client.connexcted 也只有 4w 左右，而在线连接还是 4.8w，那就不是你插件日志的问题了，建议整理最小复现提 issue。
  • 如果 client.connected 接近 4.8w，但你的插件日志还是 4.0w，那就是插件里的日志链路在高并发下漏记。你现在是 1000/s + TLS，别再用 logger 条数做最终统计，先把 hook 里的计数改成 ETS / counters / atomics 自增，压测结束后一次性读结果。
    另外顺手看下压测的 clientid 是否完全唯一；如果存在会话接管，session.takenover 会明显上来。但这通常会让 client.connected 变多，不会解释你现在这个“在线数 > connected 日志数”的方向。