客户端频繁连接

yang · 2023 年12 月 21 日 03:44

环境

EMQX 版本：emqx- 5.3.0

问题描述：部分客户端在频繁连接，订阅，断开连接

2023-12-21T11:29:32.369421+08:00 [MQTT] app_1128@39.144.50.117:9761 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=app_1128, ProtoName=MQTT, ProtoVsn=4, CleanStart=false, KeepAlive=20, Username=张三, Password=)
2023-12-21T11:29:32.369639+08:00 [QUERY] app_1128@39.144.50.117:9761 msg: http_connector_received, connector: emqx_authn_http:2, request: {“/emqx/auth”,[{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}],<<123,34,117,115,101,114,110,97,109,101,34,58,34,233,187,132,231,163,138,34,44,34,112,97,115,115,119,111,114,100,34,58,34,54,53,101,101,98,102,56,99,45,49,98,99,99,45,52,98,53,54,45,57,48,49,54,45,54,57,102,102,98,55,50,56,50,101,57,97,34,44,34,99,108,105,101,110,116,73,100,34,58,34,97,112,112,95,49,49,50,56,34,125>>}, state: [base_path: /, connect_timeout: 15000, host: test.com, pool_name: emqx_authn_http:2, pool_type: random, port: 443, request: undefined]
2023-12-21T11:29:32.373292+08:00 [AUTHN] app_1128@39.144.50.117:9761 msg: http_response, provider: emqx_authn_http, request: [base_url: https://test.com/emqx/auth, body: {“username”:“张三”,“password”:“[password]”,“clientId”:“app_1128”}, headers: [{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}], method: post, path_query: /emqx/auth], resource: emqx_authn_http:2, response: [body: {“result”:“allow”}, headers: [{<<“server”>>,<<“nginx/1.20.1”>>},{<<“date”>>,<<“Thu, 21 Dec 2023 03:29:32 GMT”>>},{<<“content-type”>>,<<“application/json”>>},{<<“transfer-encoding”>>,<<“chunked”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“vary”>>,<<“Origin”>>},{<<“vary”>>,<<“Access-Control-Request-Method”>>},{<<“vary”>>,<<“Access-Control-Request-Headers”>>}], status: 200]
2023-12-21T11:29:32.373379+08:00 [AUTHN] app_1128@39.144.50.117:9761 msg: authenticator_result, authenticator: password_based:http, result: {ok,#{is_superuser => false,user_property => #{}}}
2023-12-21T11:29:32.373448+08:00 [AUTHN] app_1128@39.144.50.117:9761 msg: authentication_result, reason: chain_result, result: {stop,{ok,#{is_superuser => false,user_property => #{}}}}
2023-12-21T11:29:32.373633+08:00 [SUBSCRIBE] app_1128@39.144.50.117:9761 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: []], topic: app/1128
2023-12-21T11:29:32.373774+08:00 [UNSUBSCRIBE] app_1128@39.144.50.117:27927 msg: unsubscribe, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: [], subid: app_1128], topic: app/1128
2023-12-21T11:29:32.373884+08:00 [BRIDGE] app_1128@39.144.50.117:27927 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:29:32.373985+08:00 [SOCKET] app_1128@39.144.50.117:27927 msg: emqx_connection_terminated, reason: {shutdown,takenover}
2023-12-21T11:29:32.374024+08:00 [info] msg: terminate, mfa: emqx_connection:terminate/2(673), peername: 39.144.50.117:27927, clientid: app_1128, reason: {shutdown,takenover}
2023-12-21T11:29:32.374277+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:29:32.374363+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:29:32.374504+08:00 [MQTT] app_1128@39.144.50.117:9761 msg: mqtt_packet_sent, packet: CONNACK(Q0, R0, D0, AckFlags=1, ReasonCode=0)
2023-12-21T11:29:32.419594+08:00 [MQTT] app_1128@39.144.50.117:9761 msg: mqtt_packet_received, packet: SUBSCRIBE(Q1, R0, D0, PacketId=958 TopicFilters=[app/1128(#{nl => 0,qos => 2,rap => 0,rh => 0})])
2023-12-21T11:29:32.419717+08:00 [info] msg: authorization_failed_nomatch, mfa: emqx_authz:authorize_non_superuser/5(432), peername: 39.144.50.117:9761, clientid: app_1128, topic: app/1128, ipaddr: {39,144,50,117}, reason: no-match rule, username: <<233,187,132,231,163,138>>
2023-12-21T11:29:32.420137+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:29:32.420230+08:00 [SUBSCRIBE] app_1128@39.144.50.117:9761 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: []], topic: app/1128
2023-12-21T11:29:32.420313+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:29:32.420356+08:00 [MQTT] app_1128@39.144.50.117:9761 msg: mqtt_packet_sent, packet: SUBACK(Q0, R0, D0, PacketId=958, ReasonCodes=[2])
2023-12-21T11:29:41.334321+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.893561+08:00 [MQTT] app_1128@39.144.50.117:23636 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=app_1128, ProtoName=MQTT, ProtoVsn=4, CleanStart=false, KeepAlive=20, Username=张三, Password=)
2023-12-21T11:30:01.893789+08:00 [QUERY] app_1128@39.144.50.117:23636 msg: http_connector_received, connector: emqx_authn_http:2, request: {“/emqx/auth”,[{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}],<<123,34,117,115,101,114,110,97,109,101,34,58,34,233,187,132,231,163,138,34,44,34,112,97,115,115,119,111,114,100,34,58,34,54,53,101,101,98,102,56,99,45,49,98,99,99,45,52,98,53,54,45,57,48,49,54,45,54,57,102,102,98,55,50,56,50,101,57,97,34,44,34,99,108,105,101,110,116,73,100,34,58,34,97,112,112,95,49,49,50,56,34,125>>}, state: [base_path: /, connect_timeout: 15000, host: test.com, pool_name: emqx_authn_http:2, pool_type: random, port: 443, request: undefined]
2023-12-21T11:30:01.897518+08:00 [AUTHN] app_1128@39.144.50.117:23636 msg: http_response, provider: emqx_authn_http, request: [base_url: https://test.com/emqx/auth, body: {“username”:“张三”,“password”:“[password]”,“clientId”:“app_1128”}, headers: [{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}], method: post, path_query: /emqx/auth], resource: emqx_authn_http:2, response: [body: {“result”:“allow”}, headers: [{<<“server”>>,<<“nginx/1.20.1”>>},{<<“date”>>,<<“Thu, 21 Dec 2023 03:30:01 GMT”>>},{<<“content-type”>>,<<“application/json”>>},{<<“transfer-encoding”>>,<<“chunked”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“vary”>>,<<“Origin”>>},{<<“vary”>>,<<“Access-Control-Request-Method”>>},{<<“vary”>>,<<“Access-Control-Request-Headers”>>}], status: 200]
2023-12-21T11:30:01.897632+08:00 [AUTHN] app_1128@39.144.50.117:23636 msg: authenticator_result, authenticator: password_based:http, result: {ok,#{is_superuser => false,user_property => #{}}}
2023-12-21T11:30:01.897714+08:00 [AUTHN] app_1128@39.144.50.117:23636 msg: authentication_result, reason: chain_result, result: {stop,{ok,#{is_superuser => false,user_property => #{}}}}
2023-12-21T11:30:01.897894+08:00 [SUBSCRIBE] app_1128@39.144.50.117:23636 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: ], topic: app/1128
2023-12-21T11:30:01.898101+08:00 [UNSUBSCRIBE] app_1128@39.144.50.117:9761 msg: unsubscribe, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: , subid: app_1128], topic: app/1128
2023-12-21T11:30:01.898184+08:00 [BRIDGE] app_1128@39.144.50.117:9761 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.898259+08:00 [SOCKET] app_1128@39.144.50.117:9761 msg: emqx_connection_terminated, reason: {shutdown,takenover}
2023-12-21T11:30:01.898287+08:00 [info] msg: terminate, mfa: emqx_connection:terminate/2(673), peername: 39.144.50.117:9761, clientid: app_1128, reason: {shutdown,takenover}
2023-12-21T11:30:01.898921+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.898996+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.899093+08:00 [MQTT] app_1128@39.144.50.117:23636 msg: mqtt_packet_sent, packet: CONNACK(Q0, R0, D0, AckFlags=1, ReasonCode=0)
2023-12-21T11:30:01.968709+08:00 [MQTT] app_1128@39.144.50.117:23636 msg: mqtt_packet_received, packet: SUBSCRIBE(Q1, R0, D0, PacketId=959 TopicFilters=[app/1128(#{nl => 0,qos => 2,rap => 0,rh => 0})])
2023-12-21T11:30:01.968895+08:00 [info] msg: authorization_failed_nomatch, mfa: emqx_authz:authorize_non_superuser/5(432), peername: 39.144.50.117:23636, clientid: app_1128, topic: app/1128, ipaddr: {39,144,50,117}, reason: no-match rule, username: <<233,187,132,231,163,138>>
2023-12-21T11:30:01.969315+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.969419+08:00 [SUBSCRIBE] app_1128@39.144.50.117:23636 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: ], topic: app/1128
2023-12-21T11:30:01.969497+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:01.969573+08:00 [MQTT] app_1128@39.144.50.117:23636 msg: mqtt_packet_sent, packet: SUBACK(Q0, R0, D0, PacketId=959, ReasonCodes=[2])
2023-12-21T11:30:10.793777+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.164817+08:00 [MQTT] app_1128@39.144.50.117:33636 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=app_1128, ProtoName=MQTT, ProtoVsn=4, CleanStart=false, KeepAlive=20, Username=张三, Password=******)
2023-12-21T11:30:23.165051+08:00 [QUERY] app_1128@39.144.50.117:33636 msg: http_connector_received, connector: emqx_authn_http:2, request: {“/emqx/auth”,[{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}],<<123,34,117,115,101,114,110,97,109,101,34,58,34,233,187,132,231,163,138,34,44,34,112,97,115,115,119,111,114,100,34,58,34,54,53,101,101,98,102,56,99,45,49,98,99,99,45,52,98,53,54,45,57,48,49,54,45,54,57,102,102,98,55,50,56,50,101,57,97,34,44,34,99,108,105,101,110,116,73,100,34,58,34,97,112,112,95,49,49,50,56,34,125>>}, state: [base_path: /, connect_timeout: 15000, host: test.com, pool_name: emqx_authn_http:2, pool_type: random, port: 443, request: undefined]
2023-12-21T11:30:23.168735+08:00 [AUTHN] app_1128@39.144.50.117:33636 msg: http_response, provider: emqx_authn_http, request: [base_url: https://test.com/emqx/auth, body: {“username”:“张三”,“password”:“[password]”,“clientId”:“app_1128”}, headers: [{<<“accept”>>,<<“application/json”>>},{<<“cache-control”>>,<<“no-cache”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“content-type”>>,<<“application/json”>>},{<<“keep-alive”>>,<<“timeout=30, max=1000”>>}], method: post, path_query: /emqx/auth], resource: emqx_authn_http:2, response: [body: {“result”:“allow”}, headers: [{<<“server”>>,<<“nginx/1.20.1”>>},{<<“date”>>,<<“Thu, 21 Dec 2023 03:30:23 GMT”>>},{<<“content-type”>>,<<“application/json”>>},{<<“transfer-encoding”>>,<<“chunked”>>},{<<“connection”>>,<<“keep-alive”>>},{<<“vary”>>,<<“Origin”>>},{<<“vary”>>,<<“Access-Control-Request-Method”>>},{<<“vary”>>,<<“Access-Control-Request-Headers”>>}], status: 200]
2023-12-21T11:30:23.168853+08:00 [AUTHN] app_1128@39.144.50.117:33636 msg: authenticator_result, authenticator: password_based:http, result: {ok,#{is_superuser => false,user_property => #{}}}
2023-12-21T11:30:23.168936+08:00 [AUTHN] app_1128@39.144.50.117:33636 msg: authentication_result, reason: chain_result, result: {stop,{ok,#{is_superuser => false,user_property => #{}}}}
2023-12-21T11:30:23.169112+08:00 [SUBSCRIBE] app_1128@39.144.50.117:33636 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: ], topic: app/1128
2023-12-21T11:30:23.169275+08:00 [UNSUBSCRIBE] app_1128@39.144.50.117:23636 msg: unsubscribe, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: , subid: app_1128], topic: app/1128
2023-12-21T11:30:23.169384+08:00 [BRIDGE] app_1128@39.144.50.117:23636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.169462+08:00 [SOCKET] app_1128@39.144.50.117:23636 msg: emqx_connection_terminated, reason: {shutdown,takenover}
2023-12-21T11:30:23.169513+08:00 [info] msg: terminate, mfa: emqx_connection:terminate/2(673), peername: 39.144.50.117:23636, clientid: app_1128, reason: {shutdown,takenover}
2023-12-21T11:30:23.169862+08:00 [BRIDGE] app_1128@39.144.50.117:33636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.169942+08:00 [BRIDGE] app_1128@39.144.50.117:33636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.170081+08:00 [MQTT] app_1128@39.144.50.117:33636 msg: mqtt_packet_sent, packet: CONNACK(Q0, R0, D0, AckFlags=1, ReasonCode=0)
2023-12-21T11:30:23.204354+08:00 [MQTT] app_1128@39.144.50.117:33636 msg: mqtt_packet_received, packet: SUBSCRIBE(Q1, R0, D0, PacketId=960 TopicFilters=[app/1128(#{nl => 0,qos => 2,rap => 0,rh => 0})])
2023-12-21T11:30:23.204474+08:00 [info] msg: authorization_failed_nomatch, mfa: emqx_authz:authorize_non_superuser/5(432), peername: 39.144.50.117:33636, clientid: app_1128, topic: app/1128, ipaddr: {39,144,50,117}, reason: no-match rule, username: <<233,187,132,231,163,138>>
2023-12-21T11:30:23.204855+08:00 [BRIDGE] app_1128@39.144.50.117:33636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.204960+08:00 [SUBSCRIBE] app_1128@39.144.50.117:33636 msg: subscribe, sub_id: app_1128, sub_opts: [nl: 0, qos: 2, rap: 0, rh: 0, sub_props: ], topic: app/1128
2023-12-21T11:30:23.205048+08:00 [BRIDGE] app_1128@39.144.50.117:33636 msg: bridge_action, bridge_id: webhook:webhook_WH_D
2023-12-21T11:30:23.205107+08:00 [MQTT] app_1128@39.144.50.117:33636 msg: mqtt_packet_sent, packet: SUBACK(Q0, R0, D0, PacketId=960, ReasonCodes=[2])
2023-12-21T11:30:32.174879+08:00 [BRIDGE] app_1128@39.144.50.117:33636 msg: bridge_action, bridge_id: webhook:webhook_WH_D预先格式化的文本

JimMoen · 2023 年12 月 21 日 04:04

2023-12-21T11:30:01.893561+08:00 [MQTT] app_1128@39.144.50.117:23636 msg: mqtt_packet_received, packet: CONNECT(Q0, R0, D0, ClientId=app_1128, ProtoName=MQTT, ProtoVsn=4, CleanStart=false, KeepAlive=20, Username=张三, Password=)

2023-12-21T11:30:01.898259+08:00 [SOCKET] app_1128@39.144.50.117:9761 msg: emqx_connection_terminated, reason: {shutdown,takenover}

app_1128 多个客户端使用了同一个 clientid 上线，互相踢
或是同一个客户端在没有正常断开连接时就重复发送了 CONNECT 报文开启了新连接。

yang · 2023 年12 月 21 日 06:02

怎么查看是不是没有正常断开，或者怎么操作一下这个客户端能让他正常了，clientId重复不会的

JimMoen · 2023 年12 月 21 日 06:26

日志中没有 DISCONNECT ，代表客户端没有发送过 DISCONNECT 报文进行断连操作
你可以参考下这篇帖子，对比看一下你的日志。

yang · 2023 年12 月 21 日 07:23

重复订阅会断开连接吗？我有做客户端事件的监听存到数据库中了

看事件在频繁的断开->连接->订阅

JimMoen · 2023 年12 月 21 日 08:19

“断开事件” 只是记录事件发生了，断开发生的原因是有个使用 app_1128 作为 clientid 的客户端上线把它挤下去了。
从你发的日志中也没有看到 app_1128 发送 MQTT DISCONNECT 报文主动断开的任何记录。
断开原因你可以在规则引擎里面看一下断开事件的 reason

应该也是 takenover

2023-12-21T11:30:01.898259+08:00 [SOCKET] app_1128@39.144.50.117:9761 msg: emqx_connection_terminated, reason: {shutdown,takenover}

yang · 2023 年12 月 22 日 02:54

谢谢回复，客户端存在某种行为以后会创建相同clientId连接造成的