unexpected info shared_sub_ack

环境信息

  • EMQX 版本:4.2.12
  • 操作系统及版本:docker
  • 其他

问题描述

3000个mqtt连接,每秒发送一次温湿度消息,运行17小时,间断性的出现连接被reset、closed、timeout

配置文件及日志

客户端日志:
nohup.zip (60.6 KB)
emqx日志:



emqx pod内存监控:
并未限制pod内存上限

linux内存监控:

4.2 已经退出维护很久了,不建议使用,你可以尝试升级到 4.4 或者 5.0

已升级到4.4.4,emq没有错误日志了,但是客户端还是存在连接断开现象

新版本有报什么错误日志么?

或者你开下那个断开连接的日志追踪看看它的详细日志

新版本emqx没有错误日志,日志追踪需要指定ClientID 或 Topic 或 IP,但是报错的mqtt客户端是随机的,指定了不一定会报错。。日志追踪没太有用

升级版本后设备端报错减少了,但还是有一些断开连接的报错。忘说了一点,emqx是集群方式部署的

是否集群没关系的,主要需要日志来看看是为什么会有断开的现象

报错日志如下:
emq0917.zip (2.2 KB)

这日志报错也是 v4.4.4 版本的么,看日志一共有3种类型的错误:
1:

2022-09-17T00:01:18.711330+00:00 [error] CF9LAe3gg4H@mock-dev-2084@10.244.0.1:40268 [Channel] Unexpected info: {#Ref<0.2620680348.3515351041.249704>,shared_sub_ack}

这个暂时还无法确定原因,只能猜测是 CF9LAe3gg4H@mock-dev-2084 这个设备在派发共享订阅的消息时,收到了一个过时的 共享订阅者的确认消息,猜测这个主题上的共享订阅者都比较忙,导致处理不过来。后果可能会有消息被重复投递到几个共享订阅者了。

2:

2022-09-17T00:01:18.683233+00:00 [warning] action: kick, file: emqx_cm.erl, line: 345, mfa: {emqx_cm,request_stepdown,3}, msg: session_stepdown_request_timeout, pid: <47162.21648.2300>, stale_channel: [{status,waiting},{message_queue_len,6},{current_stacktrace,[{emqx_shared_sub,dispatch_with_ack,5,[{file,"emqx_shared_sub.erl"},{line,195}]},{emqx_shared_sub,dispatch,5,[{file,"emqx_shared_sub.erl"},{line,143}]},{emqx_broker,do_route,2,[{file,"emqx_broker.erl"},{line,248}]},{emqx_broker,'-route/2-fun-0-',3,[{file,"emqx_broker.erl"},{line,236}]},{lists,foldl,3,[{file,"lists.erl"},{line,1267}]},{emqx_broker,safe_publish,1,[{file,"emqx_broker.erl"},{line,213}]},{emqx_hooks,safe_execute,2,[{file,"emqx_hooks.erl"},{line,207}]},{emqx_hooks,do_run,2,[{file,"emqx_hooks.erl"},{line,173}]},{emqx_channel,ensure_disconnected,2,[{file,"emqx_channel.erl"},{line,1738}]},{emqx_channel,handle_call,2,[{file,"emqx_channel.erl"},{line,959}]},{emqx_connection,handle_call,3,[{file,"emqx_connection.erl"},{line,596}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,430}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,394}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,358}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}]}]

看起了是有人操作了 页面的踢出、或者 CLI 的 kick。然被踢的这个客户端卡死了,所以强制杀死了。卡死的原因,还是由于 emqx_shared_sub:dispatch_with_ack 这个函数卡主了,原因应该和1类似(猜测这个主题上的共享订阅者都比较忙,导致处理不过来)

3:

2022-09-17T00:01:40.173456+00:00 [warning] [CM] kicked_an_unknown_session CF9LAe3gg4H@mock-dev-2725

这个没关系的,不用管。踢设备的时候,发现已经下线了。

所以,综上还只有个猜测:猜测这个主题上的共享订阅者都比较忙,导致处理不过来,而导致的后续这些错误日志

方便细化下场景么?例如多少订阅者,订阅了那些主题/共享订阅的主题,多少个发布者,消息发布的主题和频率。是否有规则引擎,或者插件 需要处理这些消息。

ps: 也可以使用 emqx 后台监控下进程运行情况(类似 top命令)

  1. 执行 bin/emqx remote_console 进入 emqx 后台
  2. 后台中输入 observer_cli:start(). 然后回车
  3. 输入 mq 按消息队列阻塞数排序,显示进程。排队数大于0就是有阻塞了(我猜你的很多订阅者应该都有卡的)
  4. 输入 q 回车退出。在 CTRL+C 退出后台

2022-09-17T00:01:18.711330+00:00 [error] CF9LAe3gg4H@mock-dev-2084@10.244.0.1:40268 [Channel] Unexpected info: {#Ref<0.2620680348.3515351041.249704>,shared_sub_ack}

这里我看代码,等待 5s 后就抛出超时,然后还是同步的,感觉这样不是很好?

observer_cli:


dashbroad:


相关监控指标:

之前给出的日志是设备端的日志,下面是消费者的日志:


您之前分析的原因大概率是因为消费者也被emqx断开了连接导致的,消费者使用了共享订阅的功能,并且会踢除相同用户名的客户端。

细化场景:
8个客户端共享订阅了两个主题:
$share/proxy/up/dev/+/+
$share/proxy/$SYS/brokers/+/clients/+/+
3000个设备(发布者)每秒发送一条mqtt消息(包含温湿度,数据很小)
未使用规则引擎,只额外启用了emqx_auth_mysql 插件,其余插件都为默认状态