客户端一直重连，Timed out waiting for a response from the server

dam.feng · 2023 年8 月 25 日 03:26

环境

EMQX 版本：4.3.22
操作系统版本：CentOS 7.9

重现此问题的步骤

运行5个EMQX，全都是单机非集群模式部署
其中3个节点运行一段时间后出现隔几分钟重连的问题
重启3个中的1个后恢复，剩下两个依然重连
消息量极低
5.客户端消费消息没有异常报错

这个是BUG吗，5台EMQX配置完全，只有其中3台出问题，重启其中1台后恢复旧无法重现，但剩下2台依然会重连

dam.feng · 2023 年8 月 25 日 03:28

2023-08-25T11:10:39.769449+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:10:39.769516+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PINGRESP(Q0, R0, D0)
2023-08-25T11:11:39.769621+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] RECV <<192,0>>
2023-08-25T11:11:39.769714+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:11:39.769775+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PINGRESP(Q0, R0, D0)
2023-08-25T11:12:31.999193+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PUBLISH(Q1, R0, D1Topic=access-transmit//sys/11033047N/39439027/thing/event/property/post, PacketId=1, Payload={“params”:{“powerSwitch”:{“value”:0,“time”:1692387611},“workMode”:{“value”:1,“time”:1692387611},“targetTemperature”:{“value”:22,“time”:1692387611},“currentTemperature”:{“value”:29,“time”:1692387611},“windSpeed7Gear”:{“value”:0,“time”:1692387611},“windSpeedAutoSwitch”:{“value”:1,“time”:1692387611},“horizontalWind”:{“value”:1,“time”:1692387611},“verticalWind”:{“value”:0,“time”:1692387611},“horizontalDirection”:{“value”:1,“time”:1692387611},“verticalDirection”:{“value”:8,“time”:1692387611},“ECO”:{“value”:0,“time”:1692387611},“selfClean”:{“value”:0,“time”:1692387611},“screen”:{“value”:1,“time”:1692387611},“PTC”:{“value”:0,“time”:1692387611},“sleep”:{“value”:0,“time”:1692387611}},“msgId”:“1692387611_126678”,“version”:“1.0”})
2023-08-25T11:12:39.769556+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] RECV <<192,0>>
2023-08-25T11:12:39.769664+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:12:39.769713+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PINGRESP(Q0, R0, D0)
2023-08-25T11:13:01.999694+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PUBLISH(Q1, R0, D1Topic=access-transmit//sys/11033047N/39439027/thing/event/property/post, PacketId=1, Payload={“params”:{“powerSwitch”:{“value”:0,“time”:1692387611},“workMode”:{“value”:1,“time”:1692387611},“targetTemperature”:{“value”:22,“time”:1692387611},“currentTemperature”:{“value”:29,“time”:1692387611},“windSpeed7Gear”:{“value”:0,“time”:1692387611},“windSpeedAutoSwitch”:{“value”:1,“time”:1692387611},“horizontalWind”:{“value”:1,“time”:1692387611},“verticalWind”:{“value”:0,“time”:1692387611},“horizontalDirection”:{“value”:1,“time”:1692387611},“verticalDirection”:{“value”:8,“time”:1692387611},“ECO”:{“value”:0,“time”:1692387611},“selfClean”:{“value”:0,“time”:1692387611},“screen”:{“value”:1,“time”:1692387611},“PTC”:{“value”:0,“time”:1692387611},“sleep”:{“value”:0,“time”:1692387611}},“msgId”:“1692387611_126678”,“version”:“1.0”})
2023-08-25T11:13:32.000695+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [MQTT] SEND PUBLISH(Q1, R0, D1Topic=access-transmit//sys/11033047N/39439027/thing/event/property/post, PacketId=1, Payload={“params”:{“powerSwitch”:{“value”:0,“time”:1692387611},“workMode”:{“value”:1,“time”:1692387611},“targetTemperature”:{“value”:22,“time”:1692387611},“currentTemperature”:{“value”:29,“time”:1692387611},“windSpeed7Gear”:{“value”:0,“time”:1692387611},“windSpeedAutoSwitch”:{“value”:1,“time”:1692387611},“horizontalWind”:{“value”:1,“time”:1692387611},“verticalWind”:{“value”:0,“time”:1692387611},“horizontalDirection”:{“value”:1,“time”:1692387611},“verticalDirection”:{“value”:8,“time”:1692387611},“ECO”:{“value”:0,“time”:1692387611},“selfClean”:{“value”:0,“time”:1692387611},“screen”:{“value”:1,“time”:1692387611},“PTC”:{“value”:0,“time”:1692387611},“sleep”:{“value”:0,“time”:1692387611}},“msgId”:“1692387611_126678”,“version”:“1.0”})
2023-08-25T11:13:39.770053+08:00 [info] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 [Shared Sub] Redispatching 1 shared subscription message(s)
2023-08-25T11:13:39.770126+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:57826 msg: terminate
reason: {shutdown,tcp_closed}
2023-08-25T11:13:41.077108+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 client_id: <<“dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111”>>
msg: insert_channel_info
2023-08-25T11:13:41.077237+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] SEND CONNACK(Q0, R0, D0AckFlags=0, ReasonCode=0)
2023-08-25T11:13:41.087339+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV <<130,57,0,33,0,52,36,115,104,97,114,101,47,97,99,99,101,115,115,45,115,117,98,115,99,114,105,112,116,105,111,110,45,115,101,114,118,105,99,101,47,97,99,99,101,115,115,45,116,114,97,110,115,109,105,116,47,35,1>>
2023-08-25T11:13:41.087420+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV SUBSCRIBE(Q1, R0, D0PacketId=33, TopicFilters=[{<<“$share/access-subscription-service/access-transmit/#”>>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2023-08-25T11:13:41.087616+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [WebHook] Send to: “/access-subscription/mqtt/subscription/event/broker-device-172.23.245.254”, params: {“username”:“iot-admin-access”,“topic”:“access-transmit/#”,“opts”:{“share”:“access-subscription-service”,“rh”:0,“rap”:0,“qos”:1,“nl”:0},“node":"emqx@172.23.245.254”,“clientid”:“dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111”,“action”:“client_subscribe”}
2023-08-25T11:13:41.102619+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] SEND SUBACK(Q0, R0, D0PacketId=33, ReasonCodes=[1])
2023-08-25T11:14:41.087995+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV <<192,0>>
2023-08-25T11:14:41.088085+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:14:41.088157+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] SEND PINGRESP(Q0, R0, D0)
2023-08-25T11:15:41.088094+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV <<192,0>>
2023-08-25T11:15:41.088180+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:15:41.088234+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] SEND PINGRESP(Q0, R0, D0)

dam.feng · 2023 年8 月 25 日 03:51

主要修改了鉴权的配置

auth_order = jwt,http
acl_order = mnesia,http

Shawn · 2023 年8 月 25 日 05:39

从你的日志里，没看出有掉线的情况。只有一个比较反常的现象：

2023-08-25T11:14:41.088085+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV PINGREQ(Q0, R0, D0)
2023-08-25T11:14:41.088157+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] SEND PINGRESP(Q0, R0, D0)
2023-08-25T11:15:41.088180+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:59438 [MQTT] RECV PINGREQ(Q0, R0, D0)

同一个 MQTT 客户端，在 1ms 内发送了 3 次 PINGREQ。看起来像是 MQTT 客户端或者网络部署的问题。

dam.feng · 2023 年8 月 25 日 05:51

可以排除是网络问题，验证过很多次网络的原因了

dam.feng · 2023 年8 月 25 日 05:53

刚把日志中的topic复制出来，发现神奇的一幕

每当出现这种情况，旧断连了，这个topic是被啥子转义了吗？如果是，怎么避免

dam.feng · 2023 年8 月 25 日 06:05

这是从服务器上导出的log文件，显示出来的，直接在服务器上看是正常的

dam.feng · 2023 年8 月 25 日 08:02

补充日志

2023-08-25T11:28:32.383633+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:47310 [MQTT] SEND PUBLISH(Q1, R0, D1Topic=access-transmit//sys/11033047N/39439027/thing/event/property/post, PacketId=1, Payload={“params”:{“powerSwitch”:{“value”:0,“time”:1692387611},“workMode”:{“value”:1,“time”:1692387611},“targetTemperature”:{“value”:22,“time”:1692387611},“currentTemperature”:{“value”:29,“time”:1692387611},“windSpeed7Gear”:{“value”:0,“time”:1692387611},“windSpeedAutoSwitch”:{“value”:1,“time”:1692387611},“horizontalWind”:{“value”:1,“time”:1692387611},“verticalWind”:{“value”:0,“time”:1692387611},“horizontalDirection”:{“value”:1,“time”:1692387611},“verticalDirection”:{“value”:8,“time”:1692387611},“ECO”:{“value”:0,“time”:1692387611},“selfClean”:{“value”:0,“time”:1692387611},“screen”:{“value”:1,“time”:1692387611},“PTC”:{“value”:0,“time”:1692387611},“sleep”:{“value”:0,“time”:1692387611}},“msgId”:“1692387611_126678”,“version”:“1.0”})
2023-08-25T11:28:42.406240+08:00 [info] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:47310 [Shared Sub] Redispatching 1 shared subscription message(s)
2023-08-25T11:28:42.406311+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:47310 msg: terminate
reason: {shutdown,tcp_closed}
2023-08-25T11:28:43.714616+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 client_id: <<“dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111”>>
msg: insert_channel_info
2023-08-25T11:28:43.714723+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 [MQTT] SEND CONNACK(Q0, R0, D0AckFlags=0, ReasonCode=0)
2023-08-25T11:28:43.730539+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 [MQTT] RECV <<130,57,0,35,0,52,36,115,104,97,114,101,47,97,99,99,101,115,115,45,115,117,98,115,99,114,105,112,116,105,111,110,45,115,101,114,118,105,99,101,47,97,99,99,101,115,115,45,116,114,97,110,115,109,105,116,47,35,1>>
2023-08-25T11:28:43.730602+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 [MQTT] RECV SUBSCRIBE(Q1, R0, D0PacketId=35, TopicFilters=[{<<“$share/access-subscription-service/access-transmit/#”>>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2023-08-25T11:28:43.730842+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 [WebHook] Send to: “/access-subscription/mqtt/subscription/event/broker-device-172.23.245.254”, params: {“username”:“iot-admin-access”,“topic”:“access-transmit/#”,“opts”:{“share”:“access-subscription-service”,“rh”:0,“rap”:0,“qos”:1,“nl”:0},“node":"emqx@172.23.245.254”,“clientid”:“dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111”,“action”:“client_subscribe”}
2023-08-25T11:28:43.744859+08:00 [debug] dev-access-subscription-service-message-a1a48b06-7cca-4fd3-ad93-0d8e17639111@172.23.16.242:33580 [MQTT] SEND SUBACK(Q0, R0, D0PacketId=35, ReasonCodes=[1])