5.4.0版本意外的断开连接事件

EMQX集群版本5.4.0

现象:日志追踪了部分终端,发现在连接的时候首先输出了CONNECT日志,在CONNECT后出现了 msg: emqx_connection_terminated, reason: {shutdown,discarded} 这样的日志,并且向系统主题输出了断开事件,但是立刻又出现了 CONNACK 日志,此时连接成功,并且输出了 SUBSCRIBE 订阅成功的事件。

该现象发生在一秒中内,这时监听终端上下线的服务会在客户端连接时先收到一个下线消息,然后又收到一条上线消息,请问可能是什么原因导致的这个问题?

详细日志如下:

2024-04-08T16:53:57.666329+08:00 [MQTT] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=1000101_efa702958078c4607e8248d610001a815308, ProtoName=MQTT, ProtoVsn=5, CleanStart=true, KeepAlive=60, Username=1000101_efa702958078c4607e8248d610001a815308, Password=******)
2024-04-08T16:53:57.666651+08:00 [AUTHN] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: user_not_found, provider: emqx_authn_mnesia
2024-04-08T16:53:57.666888+08:00 [AUTHN] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: authenticator_result, authenticator: password_based:built_in_database, result: ignore
2024-04-08T16:53:57.667172+08:00 [QUERY] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: redis_connector_received, connector: emqx_authn_redis:2, query: {cmd,[<<"HMGET">>,<<"mqtt_user:1000101_efa702958078c4607e8248d610001a815308">>,<<"password_hash">>,<<"salt">>]}, state: [pool_name: emqx_authn_redis:2, type: cluster]
2024-04-08T16:53:57.668256+08:00 [AUTHN] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: authenticator_result, authenticator: password_based:redis, result: {ok,#{is_superuser => false}}
2024-04-08T16:53:57.668527+08:00 [AUTHN] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: authentication_result, reason: chain_result, result: {stop,{ok,#{is_superuser => false}}}
2024-04-08T16:53:57.669090+08:00 [RULE] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:55881 msg: republish_message, flags: [retain: false], pub_props: [User-Property: []], topic: push/event/client_offline, payload: {"username":"1000101_efa702958078c4607e8248d610001a815308","timestamp":1712566437669,"sockname":"11.181.234.66:1883","reason":"discarded","proto_ver":5,"proto_name":"MQTT","peername":"119.147.10.243:55881","node":"emqx@11.181.234.66","metadata":{"rule_id":"rule_kkgy"},"event":"client.disconnected","disconnected_at":1712566437668,"disconn_props":{"User-Property":{}},"clientid":"1000101_efa702958078c4607e8248d610001a815308"}
2024-04-08T16:53:57.669512+08:00 [PUBLISH] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:55881 msg: publish_to, topic: push/event/client_offline, payload: {"username":"1000101_efa702958078c4607e8248d610001a815308","timestamp":1712566437669,"sockname":"11.181.234.66:1883","reason":"discarded","proto_ver":5,"proto_name":"MQTT","peername":"119.147.10.243:55881","node":"emqx@11.181.234.66","metadata":{"rule_id":"rule_kkgy"},"event":"client.disconnected","disconnected_at":1712566437668,"disconn_props":{"User-Property":{}},"clientid":"1000101_efa702958078c4607e8248d610001a815308"}
2024-04-08T16:53:57.670044+08:00 [SOCKET] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:55881 msg: emqx_connection_terminated, reason: {shutdown,discarded}
2024-04-08T16:53:57.670255+08:00 [info] msg: terminate, mfa: emqx_connection:terminate/2(673), peername: 119.147.10.243:55881, clientid: 1000101_efa702958078c4607e8248d610001a815308, reason: {shutdown,discarded}
2024-04-08T16:53:57.670253+08:00 [debug] msg: insert_channel_info, mfa: emqx_cm:insert_channel_info/3(160), peername: 119.147.10.243:40518, clientid: 1000101_efa702958078c4607e8248d610001a815308
2024-04-08T16:53:57.670482+08:00 [MQTT] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: mqtt_packet_sent, packet: CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2024-04-08T16:53:57.731985+08:00 [debug] msg: raw_bin_received, mfa: emqx_connection:when_bytes_in/3(778), peername: 119.147.10.243:40518, clientid: 1000101_efa702958078c4607e8248d610001a815308, bin: 823F0001000039707573682F313030303130312F313030303130315F65666137303239353830373863343630376538323438643631303030316138313533303800, size: 65, type: hex
2024-04-08T16:53:57.732361+08:00 [MQTT] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: mqtt_packet_received, packet: SUBSCRIBE(Q1, R0, D0, PacketId=1 TopicFilters=[push/1000101/1000101_efa702958078c4607e8248d610001a815308(#{nl => 0,qos => 0,
                                                            rap => 0,rh => 0})])

两个客户端使用了同一个 clientid 连接,在互相踢。第二个客户端连接导致了第一个客户端被踢下线。

  • 使用 45018 端口连接的客户端,发送了 CONNECT 报文
2024-04-08T16:53:57.666329+08:00 [MQTT] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:40518 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=1000101_efa702958078c4607e8248d610001a815308, ProtoName=MQTT, ProtoVsn=5, CleanStart=true, KeepAlive=60, Username=1000101_efa702958078c4607e8248d610001a815308, Password=******)
  • 使用 55881 端口的客户端被踢下线,session 被丢弃 (discarded)
2024-04-08T16:53:57.670044+08:00 [SOCKET] 1000101_efa702958078c4607e8248d610001a815308@119.147.10.243:55881 msg: emqx_connection_terminated, reason: {shutdown,discarded}