环境
-
EMQX 版本：5.0.8
-
操作系统版本：winserver 2008R2
-
EMQX 版本2：5.3.2
-
操作系统版本2：winserver 2022
重现此问题的步骤
比较难以复现，是通过很多设备连接服务器，然后抓包，当发现keepalive = 0 时候去查看抓包的协议。
预期行为
应该保证keepalive和协议中的一致
实际行为
设备连接不定期出现 keepalive = 0,通过抓包发现协议中是指定了keepalive的
看起来是一个比较难复现的问题。
仔细看了下代码，如果是有些设备显示正常，有些不正常。推测应该是获取心跳的 HTTP API 有什么 bug。下次重现时，你能在 dashboard 上 trace 一下这个有问题的客户端，看他到底是真的没有在 keepalive 倒计时(keepalive=0)，还是正常会检查。排除一下是不是 HTTP API 的问题。
一般 trace 2-3 个 keepalive 时间就会看到的。
设备离线后这条记录也会一直存在，另外的keepalive不为零的到期能自动踢掉。一开始我们业务那测反馈设备关机很久，有的设备关机后平台一直显示在线，查下后发现这个keepalive=0的记录一直存在。
dashboard 上 trace 一下这个有问题的客户端，看他到底是真的没有在 keepalive 倒计时(keepalive=0)，还是正常会检查。
这个检查需要在注册的时间的几分钟内么？还是任意时间都可以。因为这个复现时间不固定基本挂几个小时上去看下可能有一天台出现。
当设备断电关机后，经过一个周期，另一条连接的记录Pub已经没有了，其中这条Sub的记录keepalive会一直存在。
不确定是否和同一个设备使用两个不同clientid有关，目前发现都是其中一条有概率出现。通过软件模拟并发连接，并不能复现。
A980016Sub.zip (655 字节)
A980016Pub.zip (1.5 KB)
Pub日志如下：
2024-12-26T14:35:31.523000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:35:31.521304+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:35:31.521407+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:36:31.610000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:36:31.619478+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:36:31.619478+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:37:31.736000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:37:31.739873+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:37:31.739975+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:38:31.860000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:38:31.859755+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:38:31.859858+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:39:31.979000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:39:31.979331+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:39:31.979331+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:40:32.098000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:40:32.099930+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:40:32.099930+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:41:32.211000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:41:32.220325+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:41:32.220427+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:42:32.332000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:42:32.339491+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:42:32.339593+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:43:31.770000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: 3480020006247370657063008324636D643D676574737461747573267374617475733D7B22494D4549223A22383637343933303737343336393436222C226465766963655F6964223A32322C226465766963655F74797065223A3135322C226578745F706F7765725F766F6C74223A2231322E3532222C226861726477617265566572223A2266637556322E315F3230323430373138222C226963636964223A223839383630343839303232334430303035333930222C227369676E616C5F3467223A222D3831222C22736F6C61725F766F6C74223A22302E3331222C2273775F76657273696F6E223A2232303234313231333039303535302E76657273696F6E227D, size: 259, type: hex
2024-12-26T14:43:31.767658+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PUBLISH(Q2, R0, D0, Topic=$spepc, PacketId=131, Payload=******)
2024-12-26T14:43:31.767760+08:00 [AUTHZ] 980016.Pub@111.55.9.47:2331 msg: authorization_module_nomatch, ipaddr: {111,55,9,47}, module: emqx_authz_client_info, pub_sub: [action_type: publish, qos: 2, retain: false], topic: $spepc, username: 980016
2024-12-26T14:43:31.767965+08:00 [QUERY] 980016.Pub@111.55.9.47:2331 msg: mysql_connector_received, connector: emqx_authz_mysql:1, sql: emqx_authz_mysql, state: [pool_name: emqx_authz_mysql:1, prepares: ok, query_templates: [{emqx_authz_mysql,prepstmt}: {[<<“select permission, action, topic from t_mqtt_acl where ipaddr =? or username = ? or username = ‘$all’ or clientid = ? order by permission”>>],}]]
2024-12-26T14:43:31.770000+08:00 [info] msg: authorization_permission_allowed, mfa: emqx_authz:log_allowed/1(507), peername: 111.55.9.47:2331, clientid: 980016.Pub, topic: $spepc, ipaddr: {111,55,9,47}, source: mysql, username: <<“980016”>>
2024-12-26T14:43:31.769501+08:00 [PUBLISH] 980016.Pub@111.55.9.47:2331 msg: publish_to, topic: $spepc, payload: ******
2024-12-26T14:43:31.769603+08:00 [BRIDGE] 980016.Pub@111.55.9.47:2331 msg: bridge_action, bridge_id: {bridge_v2,http,message_publish}
2024-12-26T14:43:31.769910+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PUBREC(Q0, R0, D0, PacketId=131, ReasonCode=16)
2024-12-26T14:43:31.833000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: 62020083, size: 4, type: hex
2024-12-26T14:43:31.835447+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PUBREL(Q1, R0, D0, PacketId=131, ReasonCode=0)
2024-12-26T14:43:31.835447+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PUBCOMP(Q0, R0, D0, PacketId=131, ReasonCode=0)
2024-12-26T14:44:31.962000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2331, clientid: 980016.Pub, bin: C000, size: 2, type: hex
2024-12-26T14:44:31.959323+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:44:31.959323+08:00 [MQTT] 980016.Pub@111.55.9.47:2331 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:47:21.840424+08:00 [SOCKET] 980016.Pub@111.55.9.47:2331 msg: socket_force_closed, reason: keepalive_timeout
2024-12-26T14:47:21.840731+08:00 [BRIDGE] 980016.Pub@111.55.9.47:2331 msg: bridge_action, bridge_id: {bridge_v2,http,disconnected}
2024-12-26T14:47:21.840936+08:00 [SOCKET] 980016.Pub@111.55.9.47:2331 msg: emqx_connection_terminated, reason: {shutdown,keepalive_timeout}
2024-12-26T14:47:21.845000+08:00 [info] msg: terminate, mfa: emqx_connection:terminate/2(673), peername: 111.55.9.47:2331, clientid: 980016.Pub, reason: {shutdown,keepalive_timeout}
2024-12-26T15:04:57.999935+08:00 [API] 980016.Pub@ msg: trace_stopping,
Sub日志如下：
2024-12-26T14:35:46.575000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:35:46.579819+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:35:46.579819+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:36:46.679000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:36:46.687926+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:36:46.688028+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:37:46.794000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:37:46.799412+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:37:46.799514+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:38:46.925000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:38:46.927896+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:38:46.927998+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:39:47.038000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:39:47.039791+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:39:47.039791+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:40:46.154000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:40:46.160142+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:40:46.160142+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:41:46.279000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:41:46.279513+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:41:46.279615+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:42:46.390000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:42:46.400214+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:42:46.400214+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:43:46.518000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:43:46.519892+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:43:46.519995+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T14:44:46.644000+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 111.55.9.47:2332, clientid: 980016.Sub, bin: C000, size: 2, type: hex
2024-12-26T14:44:46.639468+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_received, packet: PINGREQ(Q0, R0, D0)
2024-12-26T14:44:46.639570+08:00 [MQTT] 980016.Sub@111.55.9.47:2332 msg: mqtt_packet_sent, packet: PINGRESP(Q0, R0, D0)
2024-12-26T15:04:45.978211+08:00 [API] 980016.Sub@ msg: trace_stopping,
trace 日志在上面，看起来Pub有检测断开，Sub没有检测。应该和HTTP API没有关系了
这个现场 debug 看看。
麻烦加一下我微信 zhongwencool，我远程看看
此贴终结，是 put /clients/:clientid/keepalive 修改了，感谢官方协助排查。