EMQX v4.4.6 报错 Force to close the socket due to keepalive_timeout

环境信息

  • EMQX 版本:4.4.6(docker 镜像:emqx/emqx:4.4.6)
  • 操作系统及版本:宿主机:macOS Monterey,Docker image:emqx/emqx:4.4.6
  • 其他

问题描述

参考 如何在 PHP 项目中使用 MQTT | EMQ
使用 100 个 subscriber 订阅共享主题,1 个 publisher 每隔 1s 发布一次、一共发布 2000 个消息,观察 EMQX 日志,发现有 100 多条 Force to close the socket due to keepalive_timeout 的记录:

2022-08-20T03:44:26.913206+00:00 [info] 1091@172.21.0.5:41874 1091 SUBSCRIBE test: Options: #{nl => 0,qos => 0,rap => 0,rh => 0,share => <<"g1">>,sub_props => #{}}
2022-08-20T03:44:26.913651+00:00 [debug] 1091@172.21.0.5:41874 [MQTT] SEND SUBACK(Q0, R0, D0PacketId=1, ReasonCodes=[0])
2022-08-20T03:44:27.625428+00:00 [debug] 1075@172.21.0.5:41734 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.625799+00:00 [debug] 1075@172.21.0.5:41734 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.626012+00:00 [debug] 1075@172.21.0.5:41734 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:27.632997+00:00 [debug] 1065@172.21.0.5:41836 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.633426+00:00 [debug] 1065@172.21.0.5:41836 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.634189+00:00 [debug] 1065@172.21.0.5:41836 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:27.672840+00:00 [debug] 1019@172.21.0.5:41838 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.673143+00:00 [debug] 1019@172.21.0.5:41838 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.673295+00:00 [debug] 1019@172.21.0.5:41838 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:27.740899+00:00 [debug] 1040@172.21.0.5:41686 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.741376+00:00 [debug] 1040@172.21.0.5:41686 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.742206+00:00 [debug] 1040@172.21.0.5:41686 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:27.778276+00:00 [debug] 1014@172.21.0.5:41840 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.778498+00:00 [debug] 1014@172.21.0.5:41840 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.778711+00:00 [debug] 1014@172.21.0.5:41840 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:27.934994+00:00 [debug] 1055@172.21.0.5:41808 [MQTT] RECV <<192,0>>
2022-08-20T03:44:27.935295+00:00 [debug] 1055@172.21.0.5:41808 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:27.935417+00:00 [debug] 1055@172.21.0.5:41808 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:28.363365+00:00 [debug] 1012@172.21.0.5:41806 [MQTT] RECV <<192,0>>
2022-08-20T03:44:28.363527+00:00 [debug] 1012@172.21.0.5:41806 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:28.363933+00:00 [debug] 1012@172.21.0.5:41806 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:28.374023+00:00 [debug] 1007@172.21.0.5:41492 [MQTT] Force to close the socket due to keepalive_timeout
2022-08-20T03:44:28.374433+00:00 [info] 1007@172.21.0.5:41492 file: emqx_connection.erl, line: 550, mfa: {emqx_connection,terminate,2}, msg: terminate, pid: <0.5969.0>, reason: {shutdown,keepalive_timeout}
2022-08-20T03:44:28.375308+00:00 [info] [Shared Sub] Shared subscriber down: <0.5969.0>
2022-08-20T03:44:28.396888+00:00 [debug] 1017@172.21.0.5:41496 [MQTT] Force to close the socket due to keepalive_timeout
2022-08-20T03:44:28.397480+00:00 [info] 1017@172.21.0.5:41496 file: emqx_connection.erl, line: 550, mfa: {emqx_connection,terminate,2}, msg: terminate, pid: <0.5975.0>, reason: {shutdown,keepalive_timeout}
2022-08-20T03:44:28.398067+00:00 [info] [Shared Sub] Shared subscriber down: <0.5975.0>
2022-08-20T03:44:28.509677+00:00 [debug] 1006@172.21.0.5:41842 [MQTT] RECV <<192,0>>
2022-08-20T03:44:28.509887+00:00 [debug] 1006@172.21.0.5:41842 [MQTT] RECV PINGREQ(Q0, R0, D0)
2022-08-20T03:44:28.510136+00:00 [debug] 1006@172.21.0.5:41842 [MQTT] SEND PINGRESP(Q0, R0, D0)
2022-08-20T03:44:28.687458+00:00 [debug] 1046@172.21.0.5:41540 [MQTT] Force to close the socket due to keepalive_timeout
2022-08-20T03:44:28.688055+00:00 [info] 1046@172.21.0.5:41540 file: emqx_connection.erl, line: 550, mfa: {emqx_connection,terminate,2}, msg: terminate, pid: <0.6039.0>, reason: {shutdown,keepalive_timeout}
2022-08-20T03:44:28.688990+00:00 [info] [Shared Sub] Shared subscriber down: <0.6039.0>
2022-08-20T03:44:28.741997+00:00 [debug] 172.21.0.5:41878 [MQTT] RECV <<16,18,0,6,77,81,73,115,100,112,3,2,0,10,0,4,49,48,54,51>>
2022-08-20T03:44:28.742288+00:00 [debug] 172.21.0.5:41878 [MQTT] RECV CONNECT(Q0, R0, D0ClientId=1063, ProtoName=MQIsdp, ProtoVsn=3, CleanStart=true, KeepAlive=10, Username=undefined, Password=undefined)

配置文件及日志

keepalive_timeout 是指 emqx 检查到这个客户端心跳超期,然后断开客户端连接了,可以先试试日志追踪,把某clientid 的debug日志都输出下,看是否由于客户端没有发心跳报文导致的

打印了 debug 日志
client1001.zip (27.1 KB)

客户端上线时设置keeaplive为10秒,然后上线后一直在包,不发ping,20秒左右就断线了。
推荐:如果设置了Keealive时间,则定时于keepalive*0.75时间发个ping包。