webhook有时未能推送上下线消息

386285138 · 2022 年6 月 24 日 08:41

环境信息

EMQX 版本：4.4.1
操作系统及版本：CentOS 7.8 64位
单节点

问题描述

webhook有时未能推送上下线消息。某设备重复上线下线后，都不能触发webhook，尤其是上线通知，而与此同时其他设备上下线就能收到触发的消息。

配置文件及日志

webhook配置

web.hook.url = http://127.0.0.1:8870/mqttauth/webhook/advance

web.hook.rule.client.connected.1     = {"action": "on_client_connected"}
web.hook.rule.client.disconnected.1  = {"action": "on_client_disconnected"}

emqx.log

2022-06-22T16:23:51.893631+08:00 [warning] iedu_9161a7851@42.84.45.101:53733 [Channel] The PUBACK PacketId 100 is not found.
2022-06-22T16:23:51.893815+08:00 [warning] iedu_9161a7851@42.84.45.101:53733 [Channel] The PUBCOMP PacketId 8762 is not found
2022-06-22T16:54:48.015935+08:00 [error] iedu_9161a7851@42.84.45.101:53851 [WebHook] HTTP request error: timeout
2022-06-22T16:54:48.327939+08:00 [error] iedu_ser_1655888082017@121.196.28.130:50020 [WebHook] HTTP request error: timeout
2022-06-22T16:54:48.497948+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3918790657.53369>
2022-06-22T16:54:48.501100+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3918790657.53380>
2022-06-22T16:57:37.077676+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBACK PacketId 100 is not found.
2022-06-22T16:57:37.077850+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBCOMP PacketId 14901 is not found
2022-06-22T16:57:37.077949+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBCOMP PacketId 8762 is not found
2022-06-22T16:57:37.078031+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBCOMP PacketId 14901 is not found
2022-06-22T16:57:37.078103+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBACK PacketId 100 is not found.
2022-06-22T16:58:07.076474+08:00 [warning] iedu_9161a7851@42.84.45.101:53851 [Channel] The PUBACK PacketId 100 is not found.
2022-06-22T17:08:04.751521+08:00 [error] 101.251.194.51:49370 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<1,1,32>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<22,3,1,1,32,1,0,1,28,3,3,106,234,221,222,222,139,46,45,122,132,98,226,64,23,239,221,149,23,208,153,108,219,252,42,165,0,98,41,145,208,237,216,32,27,210,5,205,72,21,52,241,35,128,12,154,89,88,198,89,123,77,4,155,255,90,240,138,119,14,56,198,42,251,80,34,0,62,19,2,19,3,19,1,192,44,192,48,0,159,204,169,204,168,204,170,192,43,192,...>>
2022-06-22T17:08:04.824505+08:00 [error] 101.251.194.51:43145 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<1,0,189>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<22,3,1,0,189,1,0,0,185,3,3,139,219,141,180,242,30,12,18,117,100,45,170,188,90,79,75,117,46,97,226,169,102,139,110,222,171,76,248,72,233,119,210,0,0,56,192,44,192,48,0,159,204,169,204,168,204,170,192,43,192,47,0,158,192,36,192,40,0,107,192,35,192,39,0,103,192,10,192,20,0,57,192,9,192,19,0,51,0,157,0,156,0,61,0,60,0,53,0,...>>
2022-06-22T17:08:04.902787+08:00 [error] 101.251.194.51:59132 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<1,0,99>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<22,3,1,0,99,1,0,0,95,3,2,53,43,147,190,76,92,146,72,131,233,136,202,130,4,149,166,181,117,77,71,107,164,100,121,81,21,192,96,61,147,208,238,0,0,18,192,10,192,20,0,57,192,9,192,19,0,51,0,53,0,47,0,255,1,0,0,36,0,11,0,4,3,0,1,2,0,10,0,12,0,10,0,29,0,23,0,30,0,25,0,24,0,35,0,0,0,22,0,...>>
2022-06-22T17:08:04.968775+08:00 [error] 101.251.194.51:49952 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<1,0,99>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<22,3,1,0,99,1,0,0,95,3,1,35,113,214,63,111,159,198,103,201,235,249,128,137,17,46,23,41,86,112,39,232,174,219,229,74,76,183,84,12,81,143,52,0,0,18,192,10,192,20,0,57,192,9,192,19,0,51,0,53,0,47,0,255,1,0,0,36,0,11,0,4,3,0,1,2,0,10,0,12,0,10,0,29,0,23,0,30,0,25,0,24,0,35,0,0,0,22,0,...>>
2022-06-22T17:08:08.075856+08:00 [error] test@101.251.194.51:52427 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-22T17:08:08.076045+08:00 [warning] test@101.251.194.51:52427 [Channel] Client test (Username: 'undefined') login failed for not_authorized
2022-06-22T17:25:53.055937+08:00 [error] iedu_9161a7851@42.84.45.101:51683 [WebHook] HTTP request error: timeout
2022-06-22T17:25:53.370002+08:00 [error] iedu_ser_1655889947057@121.196.28.130:58536 [WebHook] HTTP request error: timeout
2022-06-22T17:25:53.585632+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3917742082.89768>
2022-06-22T17:25:53.586633+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3918790657.90268>
2022-06-22T21:02:40.307361+08:00 [error] MqttClient@65.49.20.68:41518 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-22T21:02:40.307573+08:00 [warning] MqttClient@65.49.20.68:41518 [Channel] Client MqttClient (Username: 'undefined') login failed for not_authorized
2022-06-22T21:45:39.764994+08:00 [error] CENSYS@167.248.133.63:52688 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-22T21:45:39.765207+08:00 [warning] CENSYS@167.248.133.63:52688 [Channel] Client CENSYS (Username: 'undefined') login failed for not_authorized
2022-06-23T03:33:30.161282+08:00 [error] 91.240.118.237:58973 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<0>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<18,1,0,52,0,0,1,0,0,0,21,0,6,1,0,27,0,1,2,0,28,0,12,3,0,40,0,4,255,8,0,1,85,0,0,0,77,83,83,81,76,83,101,114,118,101,114,0,201,183,0,0>>
2022-06-23T08:11:44.031105+08:00 [error] 180.149.125.171:5592 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_packet,[{mqtt_packet_header,4,false,3,true},<<"T / HTTP/1.1\r\nHost: 121.196.28.130:1883\r\nUser-Agent: Mozilla/5.0 (Win">>,#{max_size => 1048576,strict_mode => false,version => 4}],[{file,"emqx_frame.erl"},{line,224}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<"GET / HTTP/1.1\r\nHost: 121.196.28.130:1883\r\nUser-Agent: Mozilla/5.0 (Windows NT 5.1; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/60.0.3112.90 Safari/537.36\r\nAccept: */*\r\nAccept-Encoding: gzip\r\n\r\n">>
2022-06-23T08:47:32.194835+08:00 [error] MqttClient@65.49.20.69:18876 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-23T08:47:32.195056+08:00 [warning] MqttClient@65.49.20.69:18876 [Channel] Client MqttClient (Username: 'undefined') login failed for not_authorized
2022-06-23T09:33:39.001220+08:00 [error] WX@161.189.192.94:53404 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-23T09:33:39.001471+08:00 [warning] WX@161.189.192.94:53404 [Channel] Client WX (Username: 'undefined') login failed for not_authorized
2022-06-23T09:35:09.045413+08:00 [error] 161.189.192.94:40698 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<"376664383365633861643436333364396336396238653665353">>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,267}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<"333766643833656338616434363333643963363962386536653538383937393235613033653338636434">>
2022-06-23T10:02:50.626994+08:00 [error] iedu_9161a7851@42.84.45.101:60489 [WebHook] HTTP request error: timeout
2022-06-23T10:02:50.938985+08:00 [error] iedu_ser_1655949764627@121.196.28.130:50558 [WebHook] HTTP request error: timeout
2022-06-23T10:02:51.167010+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3918266370.168052>
2022-06-23T10:02:51.167207+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3919314945.155465>
2022-06-23T12:23:14.506819+08:00 [error] 101.133.143.217:48918 [MQTT] , Parse failed for function_clause, [{emqx_frame,parse_utf8_string,[<<3,0,136>>],[{file,"emqx_frame.erl"},{line,482}]},{emqx_frame,parse_packet,3,[{file,"emqx_frame.erl"},{line,225}]},{emqx_frame,parse_frame,4,[{file,"emqx_frame.erl"},{line,201}]},{emqx_connection,parse_incoming,3,[{file,"emqx_connection.erl"},{line,657}]},{emqx_connection,handle_msg,2,[{file,"emqx_connection.erl"},{line,650}]},{emqx_connection,process_msg,2,[{file,"emqx_connection.erl"},{line,396}]},{emqx_connection,handle_recv,3,[{file,"emqx_connection.erl"},{line,360}]},{proc_lib,wake_up,3,[{file,"proc_lib.erl"},{line,236}]}], Frame data:<<22,3,3,0,136,1,0,0,132,3,3,98,179,234,178,215,143,33,16,232,219,14,200,147,205,187,116,140,159,25,91,161,125,0,61,127,10,109,178,218,241,0,78,0,0,22,192,20,0,53,192,19,0,47,192,44,192,43,192,48,0,157,192,47,0,156,0,10,1,0,0,69,0,10,0,22,0,20,0,23,0,24,0,25,0,9,0,10,0,11,0,12,0,13,0,14,0,22,0,...>>
2022-06-23T22:46:43.091060+08:00 [error] CENSYS@162.142.125.211:44064 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-23T22:46:43.091284+08:00 [warning] CENSYS@162.142.125.211:44064 [Channel] Client CENSYS (Username: 'undefined') login failed for not_authorized
2022-06-24T03:37:23.705372+08:00 [error] CENSYS@167.94.138.61:48762 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-24T03:37:23.705588+08:00 [warning] CENSYS@167.94.138.61:48762 [Channel] Client CENSYS (Username: 'undefined') login failed for not_authorized
2022-06-24T11:45:58.762514+08:00 [error] MqttClient@184.105.139.69:56710 [Auth http] Deny connection from path: /mqttauth/mqtt/auth, response http code: 403
2022-06-24T11:45:58.762761+08:00 [warning] MqttClient@184.105.139.69:56710 [Channel] Client MqttClient (Username: 'undefined') login failed for not_authorized
2022-06-24T14:51:28.624686+08:00 [error] iedu_9161a7851@116.3.197.73:49317 [WebHook] HTTP request error: timeout
2022-06-24T14:51:28.933981+08:00 [error] iedu_ser_1656053482623@121.196.28.130:51644 [WebHook] HTTP request error: timeout
2022-06-24T14:51:29.105746+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3920363521.183987>
2022-06-24T14:51:29.105974+08:00 [error] ehttpc: Received 'gun_error' message from unknown stream ref: #Ref<0.3794944198.3920363521.183998>

DDDHuang · 2022 年6 月 27 日 02:37

日志中的报错有很多
1 iedu_9161a7851 设备的发消息流程不完整，看起来是QoS1 或者2 的消息没完整。
2 配置的webhook服务连不上，可以看下资源状态
3 还有设备使用了非标准的协议报文
建议逐个排查，错误太多了看不出业务问题

386285138 · 2022 年6 月 27 日 08:00

这次对客户端进行了日志追踪，发现emqx/log/emqx.log.1中未出现报错日志；
客户端在此过程中，大致经历了2此重启，日志如下，发现在离线时有webhook推送，上线时未有相关日志，配置信息如最初没变，近期emqx服务未重启未修改配置。麻烦您协助一下：

2022-06-27T15:48:47.233115+08:00 [debug] 116.3.197.73:52592 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T15:48:47.233302+08:00 [debug] 116.3.197.73:52592 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656316127233,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T15:48:47.657230+08:00 [debug] 116.3.197.73:51217 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656316127551\",\"sign\":\"cdf7bc6d1e4d7027fc8c91b7e160664a\",\"data\":{\"peikey\":\"a91b6545e15d46d89e7769d5322ff391\"}}">>)
2022-06-27T15:48:47.764641+08:00 [debug] 116.3.197.73:51217 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","reason":"tcp_closed","node":"emqx_c01@127.0.0.1","disconnected_at":1656316127764,"connected_at":1656315716105,"clientid":"iedu_9161a7851","action":"client_disconnected"}
2022-06-27T15:48:48.031005+08:00 [info] 116.3.197.73:51217     msg: terminate
    reason: {shutdown,tcp_closed}
2022-06-27T15:48:48.031320+08:00 [debug] 116.3.197.73:52592     action: discard
    msg: session_already_shutdown
    pid: <0.282.13>
2022-06-27T15:48:48.031887+08:00 [debug] 116.3.197.73:52592     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T15:48:48.031972+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T15:48:53.783356+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,26,0,2,0,21,112,114,105,107,101,121,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:48:53.783509+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"prikey/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:48:53.783666+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE prikey/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:48:53.783935+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[1])
2022-06-27T15:48:53.784186+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=prikey/iedu_9161a7851, PacketId=1, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656316127551\",\"sign\":\"cdf7bc6d1e4d7027fc8c91b7e160664a\",\"data\":{\"peikey\":\"a91b6545e15d46d89e7769d5322ff391\"}}">>)
2022-06-27T15:48:54.006329+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<64,2,0,1>>
2022-06-27T15:48:54.006464+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=1, ReasonCode=0)
2022-06-27T15:48:54.119362+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,28,0,3,0,23,118,101,114,115,105,111,110,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:48:54.119501+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=3, TopicFilters=[{<<"versions/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:48:54.119661+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE versions/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:48:54.119827+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=3, ReasonCodes=[1])
2022-06-27T15:48:59.996621+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,31,0,4,0,26,100,101,109,111,110,115,116,114,97,116,101,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,2>>
2022-06-27T15:48:59.996773+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=4, TopicFilters=[{<<"demonstrate/iedu_9161a7851">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}])
2022-06-27T15:48:59.996922+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE demonstrate/iedu_9161a7851: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:48:59.997166+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=4, ReasonCodes=[2])
2022-06-27T15:49:06.003590+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,25,0,5,0,20,97,100,111,112,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:49:06.003757+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=5, TopicFilters=[{<<"adopt/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:49:06.003913+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE adopt/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:49:06.004137+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=5, ReasonCodes=[1])
2022-06-27T15:49:06.004408+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T15:49:06.201588+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<64,2,0,2>>
2022-06-27T15:49:06.201728+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=2, ReasonCode=0)
2022-06-27T15:49:11.997888+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,27,0,6,0,22,100,101,112,111,115,105,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:49:11.998038+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=6, TopicFilters=[{<<"deposit/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:49:11.998197+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE deposit/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:49:11.998489+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=6, ReasonCodes=[1])
2022-06-27T15:49:17.994879+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,28,0,7,0,23,114,111,117,103,104,78,114,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:49:17.995024+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=7, TopicFilters=[{<<"roughNrs/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:49:17.995176+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE roughNrs/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:49:17.995412+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=7, ReasonCodes=[1])
2022-06-27T15:49:23.994131+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,30,0,8,0,25,105,110,115,112,101,99,116,105,111,110,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:49:23.994296+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=8, TopicFilters=[{<<"inspection/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:49:23.994458+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE inspection/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:49:23.994717+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=8, ReasonCodes=[1])
2022-06-27T15:49:30.000398+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<130,28,0,9,0,23,101,114,114,111,114,77,115,103,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:49:30.000563+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=9, TopicFilters=[{<<"errorMsg/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:49:30.000743+08:00 [info] 116.3.197.73:52592 iedu_9161a7851 SUBSCRIBE errorMsg/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:49:30.001030+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=9, ReasonCodes=[1])
2022-06-27T15:49:30.208395+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV <<48,211,1,0,23,112,116,82,101,112,111,114,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,49,54,49,54,51,34,44,34,115,105,103,110,34,58,34,66,50,66,69,49,67,56,53,67,68,67,54,49,48,54,48,52,49,55,70,51,49,53,70,55,66,49,48,69,67,51,52,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>
2022-06-27T15:49:30.208589+08:00 [debug] 116.3.197.73:52592 [MQTT] RECV PUBLISH(Q0, R0, D0, Topic=ptReport/iedu_9161a7851, PacketId=undefined, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656316163\",\"sign\":\"B2BE1C85CDC61060417F315F7B10EC34\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>)
2022-06-27T15:49:30.208819+08:00 [info] 116.3.197.73:52592 PUBLISH to ptReport/iedu_9161a7851: <<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656316163\",\"sign\":\"B2BE1C85CDC61060417F315F7B10EC34\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>
2022-06-27T15:51:05.167157+08:00 [debug] 116.3.197.73:62343 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T15:51:05.167361+08:00 [debug] 116.3.197.73:62343 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656316265167,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T15:51:05.524585+08:00 [debug] 116.3.197.73:52592 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656316265484\",\"sign\":\"d64c7d3dded2ef976861118ab9ae73b9\",\"data\":{\"peikey\":\"b35485aaa1a0481282c8fd1c6fe95004\"}}">>)
2022-06-27T15:51:05.597761+08:00 [debug] 116.3.197.73:52592 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","reason":"tcp_closed","node":"emqx_c01@127.0.0.1","disconnected_at":1656316265597,"connected_at":1656316127233,"clientid":"iedu_9161a7851","action":"client_disconnected"}
2022-06-27T15:51:05.674679+08:00 [info] 116.3.197.73:52592     msg: terminate
    reason: {shutdown,tcp_closed}
2022-06-27T15:51:05.674936+08:00 [debug] 116.3.197.73:62343     action: discard
    msg: session_already_shutdown
    pid: <0.518.13>
2022-06-27T15:51:05.675184+08:00 [debug] 116.3.197.73:62343     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T15:51:05.675262+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T15:51:10.977590+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,26,0,2,0,21,112,114,105,107,101,121,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:10.977746+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"prikey/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:10.977912+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE prikey/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:10.978173+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[1])
2022-06-27T15:51:10.978439+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=prikey/iedu_9161a7851, PacketId=1, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656316265484\",\"sign\":\"d64c7d3dded2ef976861118ab9ae73b9\",\"data\":{\"peikey\":\"b35485aaa1a0481282c8fd1c6fe95004\"}}">>)
2022-06-27T15:51:11.222536+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<64,2,0,1>>
2022-06-27T15:51:11.222675+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=1, ReasonCode=0)
2022-06-27T15:51:11.335551+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,28,0,3,0,23,118,101,114,115,105,111,110,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:11.335708+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=3, TopicFilters=[{<<"versions/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:11.335880+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE versions/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:11.336118+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=3, ReasonCodes=[1])
2022-06-27T15:51:17.212552+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,31,0,4,0,26,100,101,109,111,110,115,116,114,97,116,101,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,2>>
2022-06-27T15:51:17.212712+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=4, TopicFilters=[{<<"demonstrate/iedu_9161a7851">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}])
2022-06-27T15:51:17.212849+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE demonstrate/iedu_9161a7851: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:17.213090+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=4, ReasonCodes=[2])
2022-06-27T15:51:23.212792+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,25,0,5,0,20,97,100,111,112,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:23.212927+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=5, TopicFilters=[{<<"adopt/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:23.213081+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE adopt/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:23.213327+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=5, ReasonCodes=[1])
2022-06-27T15:51:23.213585+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T15:51:23.417793+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<64,2,0,2>>
2022-06-27T15:51:23.417933+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=2, ReasonCode=0)
2022-06-27T15:51:29.228054+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,27,0,6,0,22,100,101,112,111,115,105,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:29.228204+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=6, TopicFilters=[{<<"deposit/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:29.228378+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE deposit/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:29.228633+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=6, ReasonCodes=[1])
2022-06-27T15:51:35.216031+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,28,0,7,0,23,114,111,117,103,104,78,114,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:35.216189+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=7, TopicFilters=[{<<"roughNrs/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:35.216382+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE roughNrs/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:35.216638+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=7, ReasonCodes=[1])
2022-06-27T15:51:41.210333+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,30,0,8,0,25,105,110,115,112,101,99,116,105,111,110,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:41.210476+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=8, TopicFilters=[{<<"inspection/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:41.210632+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE inspection/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:41.210879+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=8, ReasonCodes=[1])
2022-06-27T15:51:47.216289+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<130,28,0,9,0,23,101,114,114,111,114,77,115,103,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T15:51:47.216446+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=9, TopicFilters=[{<<"errorMsg/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T15:51:47.216602+08:00 [info] 116.3.197.73:62343 iedu_9161a7851 SUBSCRIBE errorMsg/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T15:51:47.216870+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=9, ReasonCodes=[1])
2022-06-27T15:51:47.423290+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<48,195,1,0,23,112,116,82,101,112,111,114,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,49,54,51,48,49,34,44,34,115,105,103,110,34,58,34,53,50,57,67,65,48,203,101,130,191,19,192,252,55,221,56,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>
2022-06-27T15:51:47.423488+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV PUBLISH(Q0, R0, D0, Topic=ptReport/iedu_9161a7851, PacketId=undefined, Payload=<<123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,49,54,51,48,49,34,44,34,115,105,103,110,34,58,34,53,50,57,67,65,48,203,101,130,191,19,192,252,55,221,56,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>)
2022-06-27T15:51:47.423784+08:00 [info] 116.3.197.73:62343 PUBLISH to ptReport/iedu_9161a7851: <<123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,49,54,51,48,49,34,44,34,115,105,103,110,34,58,34,53,50,57,67,65,48,203,101,130,191,19,192,252,55,221,56,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>
2022-06-27T15:53:24.179904+08:00 [debug] 116.3.197.73:62343 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=demonstrate/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCD\",\"timestamp\":\"1656316404162\",\"version\":\"1.0.0\",\"sign\":\"f0437f36c12871be98e4b5e18b87973b\",\"data\":{\"demoList\":[{\"act\":\"SATISFACTION\",\"dur\":60},{\"act\":\"FEEDING\",\"dur\":60},{\"act\":\"HICCUP\",\"dur\":60},{\"act\":\"DIAPERS\",\"dur\":60},{\"act\":\"COUGHING\",\"dur\":60},{\"act\":\"SHAKING\",\"dur\":60},{\"act\":\"SNORING\",\"dur\":60}],\"interval\":30,\"dmid\":550344711359000576,\"stus\":1}}">>)
2022-06-27T15:53:24.349761+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV <<64,2,0,3>>
2022-06-27T15:53:24.349907+08:00 [debug] 116.3.197.73:62343 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=3, ReasonCode=0)

heeejianbo · 2022 年6 月 28 日 03:09

像一个设计问题：“在同名客户端登录过程中，两个客户端发布的 client.connected 和 client.disconnected 事件顺序存在不一致”

当前实现上 (v4.4.5 和 v4.3.16 及以下)：

A 登录到 emqx
有相同 ClientID 的客户端 B 也登录到 emqx，此时：
先触发了 B 的 client.connected 事件
再踢出了同名客户端 A，
A 由于离线触发了 client.disconnected 事件

因此在外部看来，这个客户端是离线的。

这是一个非常严重的问题 @386285138 感谢反馈！我们下个版本立马修复。

一个零时的解决方法是，忽略 disconnect 事件中错误原因为 discarded, takeovered 的事件即可。这两个原因都是由于同名客户端被踢出导致的

386285138 · 2022 年6 月 28 日 03:51

感谢您的及时回复。目前有3个疑问：
1.曾经确实是有两个设备公用一个clientId的现象，但是目前出现的问题和采集到相关日志，都是同一个设备；期间正常使用，发现问题后进行重启；会不会是单一设备进行重启时，第一次的连接虽然已经中断但是服务端未检测到掉线，重启后再连接，将第一次连接顶掉发生了问题？
2.如果我们改用开源版最新的v5.0.0，可以避免这个问题吗（我理解的是，好像不会哈）
3.我的日志中，未出现过takeovered事件，都是discarded。您的建议是，业务上认为discarded不是断线事件，直接忽略即可；
也希望上述阐述可以协助开发人员发现问题。谢谢

2022-06-27T17:00:21.814153+08:00 [debug] 116.3.197.73:53360     action: discard
    msg: session_already_shutdown
    pid: <0.2804.13>
2022-06-27T17:00:21.814780+08:00 [debug] 116.3.197.73:53360     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T17:00:21.814863+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T17:00:27.100759+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<130,26,0,2,0,21,112,114,105,107,101,121,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:00:27.100914+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"prikey/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:00:27.101099+08:00 [info] 116.3.197.73:53360 iedu_9161a7851 SUBSCRIBE prikey/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:00:27.101402+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[1])
2022-06-27T17:00:27.101689+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=prikey/iedu_9161a7851, PacketId=1, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320421550\",\"sign\":\"b6fc0c9157966cb9aea0276806f11682\",\"data\":{\"peikey\":\"47501fe07f354bd9b0fb5c393f8fe534\"}}">>)
2022-06-27T17:00:27.340744+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<64,2,0,1>>
2022-06-27T17:00:27.340877+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=1, ReasonCode=0)
2022-06-27T17:00:27.447764+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<130,28,0,3,0,23,118,101,114,115,105,111,110,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:00:27.447932+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=3, TopicFilters=[{<<"versions/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:00:27.448109+08:00 [info] 116.3.197.73:53360 iedu_9161a7851 SUBSCRIBE versions/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:00:27.448354+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=3, ReasonCodes=[1])
2022-06-27T17:00:34.490957+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<130,31,0,4,0,26,100,101,109,111,110,115,116,114,97,116,101,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,2>>
2022-06-27T17:00:34.491124+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=4, TopicFilters=[{<<"demonstrate/iedu_9161a7851">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}])
2022-06-27T17:00:34.491307+08:00 [info] 116.3.197.73:53360 iedu_9161a7851 SUBSCRIBE demonstrate/iedu_9161a7851: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:00:34.491595+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=4, ReasonCodes=[2])
2022-06-27T17:00:40.332025+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<130,25,0,5,0,20,97,100,111,112,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:00:40.332178+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=5, TopicFilters=[{<<"adopt/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:00:40.332364+08:00 [info] 116.3.197.73:53360 iedu_9161a7851 SUBSCRIBE adopt/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:00:40.332626+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=5, ReasonCodes=[1])
2022-06-27T17:00:40.332907+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T17:00:40.521982+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<112,2,112,116,64,2,119,220,98,2,34,97>>
2022-06-27T17:00:40.522163+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV PUBCOMP(Q0, R0, D0, PacketId=28788, ReasonCode=0)
2022-06-27T17:00:40.522258+08:00 [warning] 116.3.197.73:53360 [Channel] The PUBCOMP PacketId 28788 is not found
2022-06-27T17:00:40.523330+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=30684, ReasonCode=0)
2022-06-27T17:00:40.523442+08:00 [warning] 116.3.197.73:53360 [Channel] The PUBACK PacketId 30684 is not found.
2022-06-27T17:00:40.523603+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV PUBREL(Q1, R0, D0, PacketId=8801, ReasonCode=0)
2022-06-27T17:00:40.523670+08:00 [warning] 116.3.197.73:53360 [Channel] The PUBREL PacketId 8801 is not found.
2022-06-27T17:00:40.523859+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND PUBCOMP(Q0, R0, D0, PacketId=8801, ReasonCode=146)
2022-06-27T17:01:10.333996+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND PUBLISH(Q1, R1, D1, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T17:01:10.556762+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV <<64,2,0,2>>
2022-06-27T17:01:10.556913+08:00 [debug] 116.3.197.73:53360 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=2, ReasonCode=0)
2022-06-27T17:04:17.122583+08:00 [debug] 116.3.197.73:49674 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T17:04:17.122782+08:00 [debug] 116.3.197.73:49674 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656320657122,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T17:04:17.533625+08:00 [debug] 116.3.197.73:53360 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320657446\",\"sign\":\"407f4d6f7ee84a64e38fd7f2f046674f\",\"data\":{\"peikey\":\"50850deb52f74ec2a92b76b52817fad8\"}}">>)
2022-06-27T17:04:17.663223+08:00 [info] 116.3.197.73:53360     msg: terminate
    reason: {shutdown,discarded}
2022-06-27T17:04:17.663560+08:00 [debug] 116.3.197.73:49674     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T17:04:17.663642+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T17:04:22.828247+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,26,0,2,0,21,112,114,105,107,101,121,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:04:22.828420+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"prikey/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:04:22.828598+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE prikey/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:04:22.828823+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[1])
2022-06-27T17:04:22.829124+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=prikey/iedu_9161a7851, PacketId=1, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320657446\",\"sign\":\"407f4d6f7ee84a64e38fd7f2f046674f\",\"data\":{\"peikey\":\"50850deb52f74ec2a92b76b52817fad8\"}}">>)
2022-06-27T17:04:39.830499+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<64,2,0,1>>
2022-06-27T17:04:39.830631+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=1, ReasonCode=0)
2022-06-27T17:04:39.968577+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,28,0,3,0,23,118,101,114,115,105,111,110,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:04:39.968745+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=3, TopicFilters=[{<<"versions/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:04:39.968904+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE versions/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:04:39.969096+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=3, ReasonCodes=[1])
2022-06-27T17:04:45.967742+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,31,0,4,0,26,100,101,109,111,110,115,116,114,97,116,101,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,2>>
2022-06-27T17:04:45.967887+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=4, TopicFilters=[{<<"demonstrate/iedu_9161a7851">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}])
2022-06-27T17:04:45.968066+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE demonstrate/iedu_9161a7851: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:04:45.968256+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=4, ReasonCodes=[2])
2022-06-27T17:04:51.967012+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,25,0,5,0,20,97,100,111,112,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:04:51.967140+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=5, TopicFilters=[{<<"adopt/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:04:51.967325+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE adopt/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:04:51.967518+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=5, ReasonCodes=[1])
2022-06-27T17:04:51.967780+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T17:04:52.158011+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<64,2,0,2>>
2022-06-27T17:04:52.158157+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=2, ReasonCode=0)
2022-06-27T17:04:57.967012+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,27,0,6,0,22,100,101,112,111,115,105,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:04:57.967174+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=6, TopicFilters=[{<<"deposit/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:04:57.967345+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE deposit/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:04:57.967543+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=6, ReasonCodes=[1])
2022-06-27T17:05:03.965254+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,28,0,7,0,23,114,111,117,103,104,78,114,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:05:03.965418+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=7, TopicFilters=[{<<"roughNrs/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:05:03.965605+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE roughNrs/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:05:03.965877+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=7, ReasonCodes=[1])
2022-06-27T17:05:09.960223+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,30,0,8,0,25,105,110,115,112,101,99,116,105,111,110,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:05:09.960393+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=8, TopicFilters=[{<<"inspection/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:05:09.960566+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE inspection/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:05:09.960781+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=8, ReasonCodes=[1])
2022-06-27T17:05:15.961583+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<130,28,0,9,0,23,101,114,114,111,114,77,115,103,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:05:15.961733+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=9, TopicFilters=[{<<"errorMsg/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:05:15.961902+08:00 [info] 116.3.197.73:49674 iedu_9161a7851 SUBSCRIBE errorMsg/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:05:15.962093+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=9, ReasonCodes=[1])
2022-06-27T17:05:16.169445+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV <<48,211,1,0,23,112,116,82,101,112,111,114,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,50,48,55,49,48,34,44,34,115,105,103,110,34,58,34,70,70,52,69,69,56,52,56,55,55,52,65,48,70,65,66,56,65,51,49,54,50,56,55,69,54,51,70,49,49,52,70,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>
2022-06-27T17:05:16.169678+08:00 [debug] 116.3.197.73:49674 [MQTT] RECV PUBLISH(Q0, R0, D0, Topic=ptReport/iedu_9161a7851, PacketId=undefined, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656320710\",\"sign\":\"FF4EE848774A0FAB8A316287E63F114F\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>)
2022-06-27T17:05:16.169870+08:00 [info] 116.3.197.73:49674 PUBLISH to ptReport/iedu_9161a7851: <<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656320710\",\"sign\":\"FF4EE848774A0FAB8A316287E63F114F\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>
2022-06-27T17:06:50.686478+08:00 [debug] 116.3.197.73:63185 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T17:06:50.686667+08:00 [debug] 116.3.197.73:63185 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656320810686,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T17:06:51.051522+08:00 [debug] 116.3.197.73:49674 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320811005\",\"sign\":\"40b22d1c41133f856b271d432a394936\",\"data\":{\"peikey\":\"09cd5d0ab7b5432fbc3dee17b3842e86\"}}">>)
2022-06-27T17:06:51.144102+08:00 [debug] 116.3.197.73:49674 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","reason":"tcp_closed","node":"emqx_c01@127.0.0.1","disconnected_at":1656320811144,"connected_at":1656320657122,"clientid":"iedu_9161a7851","action":"client_disconnected"}
2022-06-27T17:06:51.249026+08:00 [info] 116.3.197.73:49674     msg: terminate
    reason: {shutdown,tcp_closed}
2022-06-27T17:06:51.249564+08:00 [debug] 116.3.197.73:63185     action: discard
    msg: session_already_shutdown
    pid: <0.3456.13>
2022-06-27T17:06:51.249853+08:00 [debug] 116.3.197.73:63185     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T17:06:51.249932+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T17:06:57.118899+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,26,0,2,0,21,112,114,105,107,101,121,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:06:57.119057+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=2, TopicFilters=[{<<"prikey/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:06:57.119236+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE prikey/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:06:57.119473+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=2, ReasonCodes=[1])
2022-06-27T17:06:57.119707+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=prikey/iedu_9161a7851, PacketId=1, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320811005\",\"sign\":\"40b22d1c41133f856b271d432a394936\",\"data\":{\"peikey\":\"09cd5d0ab7b5432fbc3dee17b3842e86\"}}">>)
2022-06-27T17:06:57.299859+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<64,2,0,1>>
2022-06-27T17:06:57.299989+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=1, ReasonCode=0)
2022-06-27T17:06:57.595851+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,28,0,3,0,23,118,101,114,115,105,111,110,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:06:57.596033+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=3, TopicFilters=[{<<"versions/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:06:57.596234+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE versions/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:06:57.596443+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=3, ReasonCodes=[1])
2022-06-27T17:07:03.301122+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,31,0,4,0,26,100,101,109,111,110,115,116,114,97,116,101,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,2>>
2022-06-27T17:07:03.301282+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=4, TopicFilters=[{<<"demonstrate/iedu_9161a7851">>,#{nl => 0,qos => 2,rap => 0,rh => 0}}])
2022-06-27T17:07:03.301458+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE demonstrate/iedu_9161a7851: Options: #{nl => 0,qos => 2,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:03.301679+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=4, ReasonCodes=[2])
2022-06-27T17:07:09.298139+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,25,0,5,0,20,97,100,111,112,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:07:09.298308+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=5, TopicFilters=[{<<"adopt/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:07:09.298504+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE adopt/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:09.298803+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=5, ReasonCodes=[1])
2022-06-27T17:07:09.299096+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND PUBLISH(Q1, R1, D0, Topic=adopt/iedu_9161a7851, PacketId=2, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCA\",\"timestamp\":\"1655881105\",\"version\":\"1.0.0\",\"sign\":\"63153f543a74871c5ca25679745e84a5\",\"data\":{\"adpId\":548518937293189120,\"days\":1,\"mt\":1,\"stus\":1,\"stTm\":\"2022-06-22 00:00:00\",\"edTm\":\"2022-06-27 00:00:00\",\"dinx\":0,\"minx\":0,\"d\":[{\"actId\":548518937519681536,\"idx\":0,\"act\":\"DIAPERS\",\"stTm\":\"08:46:37\",\"dur\":10,\"ned\":\"DIAPER\",\"voc1\":\"1-_2\",\"voc2\":\"rw1\",\"sftgVoc\":\"mz1\",\"sfteVoc\":\"mzjs1\"}]}}">>)
2022-06-27T17:07:09.503139+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<64,2,0,2>>
2022-06-27T17:07:09.503260+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV PUBACK(Q0, R0, D0, PacketId=2, ReasonCode=0)
2022-06-27T17:07:15.294373+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,27,0,6,0,22,100,101,112,111,115,105,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:07:15.294509+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=6, TopicFilters=[{<<"deposit/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:07:15.294672+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE deposit/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:15.294934+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=6, ReasonCodes=[1])
2022-06-27T17:07:21.293608+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,28,0,7,0,23,114,111,117,103,104,78,114,115,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:07:21.293771+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=7, TopicFilters=[{<<"roughNrs/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:07:21.293937+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE roughNrs/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:21.294139+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=7, ReasonCodes=[1])
2022-06-27T17:07:27.294638+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,30,0,8,0,25,105,110,115,112,101,99,116,105,111,110,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:07:27.294806+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=8, TopicFilters=[{<<"inspection/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:07:27.294962+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE inspection/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:27.295179+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=8, ReasonCodes=[1])
2022-06-27T17:07:33.290870+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<130,28,0,9,0,23,101,114,114,111,114,77,115,103,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,1>>
2022-06-27T17:07:33.291013+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV SUBSCRIBE(Q1, R0, D0, PacketId=9, TopicFilters=[{<<"errorMsg/iedu_9161a7851">>,#{nl => 0,qos => 1,rap => 0,rh => 0}}])
2022-06-27T17:07:33.291192+08:00 [info] 116.3.197.73:63185 iedu_9161a7851 SUBSCRIBE errorMsg/iedu_9161a7851: Options: #{nl => 0,qos => 1,rap => 0,rh => 0,sub_props => #{}}
2022-06-27T17:07:33.291409+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND SUBACK(Q0, R0, D0, PacketId=9, ReasonCodes=[1])
2022-06-27T17:07:33.489913+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV <<48,211,1,0,23,112,116,82,101,112,111,114,116,47,105,101,100,117,95,57,49,54,49,97,55,56,53,49,123,34,99,108,105,101,110,116,105,100,34,58,34,105,101,100,117,95,57,49,54,49,97,55,56,53,49,34,44,34,97,99,116,105,111,110,34,58,34,68,80,82,34,44,34,116,105,109,101,115,116,97,109,112,34,58,34,49,54,53,54,51,50,48,56,52,55,34,44,34,115,105,103,110,34,58,34,53,68,49,69,53,50,51,57,67,50,70,51,66,69,65,50,50,51,55,55,70,49,70,55,49,50,67,57,65,55,66,53,34,44,34,118,101,114,115,105,111,110,34,58,34,49,46,48,46,48,34,44,34,100,97,116,97,34,58,123,34,116,121,112,101,34,58,34,50,34,44,34,116,115,34,58,48,44,34,103,121,34,58,49,44,34,103,115,34,58,49,44,34,105,99,34,58,49,44,34,97,117,34,58,48,125,125,13,10>>
2022-06-27T17:07:33.490136+08:00 [debug] 116.3.197.73:63185 [MQTT] RECV PUBLISH(Q0, R0, D0, Topic=ptReport/iedu_9161a7851, PacketId=undefined, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656320847\",\"sign\":\"5D1E5239C2F3BEA22377F1F712C9A7B5\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>)
2022-06-27T17:07:33.490315+08:00 [info] 116.3.197.73:63185 PUBLISH to ptReport/iedu_9161a7851: <<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"DPR\",\"timestamp\":\"1656320847\",\"sign\":\"5D1E5239C2F3BEA22377F1F712C9A7B5\",\"version\":\"1.0.0\",\"data\":{\"type\":\"2\",\"ts\":0,\"gy\":1,\"gs\":1,\"ic\":1,\"au\":0}}\r\n">>
2022-06-27T17:09:27.399220+08:00 [debug] 116.3.197.73:63441 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T17:09:27.399420+08:00 [debug] 116.3.197.73:63441 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656320967399,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T17:09:27.756767+08:00 [debug] 116.3.197.73:63185 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656320967714\",\"sign\":\"16b867a6fa8fd29a3d8e0df4700e513f\",\"data\":{\"peikey\":\"5a13494b6304435bb6a326ab451410aa\"}}">>)
2022-06-27T17:09:27.832758+08:00 [debug] 116.3.197.73:63185 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","reason":"tcp_closed","node":"emqx_c01@127.0.0.1","disconnected_at":1656320967832,"connected_at":1656320810686,"clientid":"iedu_9161a7851","action":"client_disconnected"}
2022-06-27T17:09:27.906002+08:00 [info] 116.3.197.73:63185     msg: terminate
    reason: {shutdown,tcp_closed}
2022-06-27T17:09:27.906215+08:00 [debug] 116.3.197.73:63441     action: discard
    msg: session_already_shutdown
    pid: <0.3541.13>
2022-06-27T17:09:27.906478+08:00 [debug] 116.3.197.73:63441     client_id: <<"iedu_9161a7851">>
    msg: insert_channel_info
2022-06-27T17:09:27.906575+08:00 [debug] 116.3.197.73:63441 [MQTT] SEND CONNACK(Q0, R0, D0, AckFlags=0, ReasonCode=0)
2022-06-27T17:10:21.254377+08:00 [debug] 116.3.197.73:62855 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T17:10:21.254587+08:00 [debug] 116.3.197.73:62855 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656321021254,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T17:10:21.731200+08:00 [info] 116.3.197.73:63441     msg: terminate
    reason: {shutdown,discarded}

heeejianbo · 2022 年6 月 28 日 04:09

A1: 是的
A2: 5.0.0 也还是有的，我们会计划在三个大版本上都出一个bugfix版本来修复它
A3: 是的，可以忽略的

386285138 · 2022 年6 月 28 日 04:20

好的谢谢您的帮助

386285138 · 2022 年6 月 28 日 08:51

您提出的临时解决方案，我尝试了一下，好像还不能解决：
因为我现在只有以下两个webhook订阅，并没有‘session.discarded’或‘session.terminated’：

web.hook.rule.client.connected.1     = {"action": "on_client_connected"}
web.hook.rule.client.disconnected.1  = {"action": "on_client_disconnected"}

而且从以下日志看，我确实收到了有关‘on_client_disconnected’的webhook推送，该推送的详细内容中，reason仅为‘tcp_closed’，更详细的（客户端日志内显示出的）‘ action: discard’我是获取不到的，或者可以通过什么方式获取到呢？
这里我也不太理解，action到底是‘on_client_disconnected’还是‘discard’，还是说，前者包含了后者；我没有订阅‘action:discard’相关内容，也没有对其进行业务处理，为什么会收到相关推送呢，是不是我的配置存在问题。

2022-06-27T15:48:47.233115+08:00 [debug] 116.3.197.73:52592 [Channel] RECV CONNECT(Q0, R0, D0, ClientId=iedu_9161a7851, ProtoName=MQTT, ProtoVsn=4, CleanStart=true, KeepAlive=600, Username=test, Password=******)
2022-06-27T15:48:47.233302+08:00 [debug] 116.3.197.73:52592 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","proto_ver":4,"node":"emqx_c01@127.0.0.1","keepalive":600,"ipaddress":"116.3.197.73","connected_at":1656316127233,"clientid":"iedu_9161a7851","action":"client_connected"}
2022-06-27T15:48:47.657230+08:00 [debug] 116.3.197.73:51217 [MQTT] SEND PUBLISH(Q1, R0, D0, Topic=prikey/iedu_9161a7851, PacketId=3, Payload=<<"{\"clientid\":\"iedu_9161a7851\",\"action\":\"SCK\",\"timestamp\":\"1656316127551\",\"sign\":\"cdf7bc6d1e4d7027fc8c91b7e160664a\",\"data\":{\"peikey\":\"a91b6545e15d46d89e7769d5322ff391\"}}">>)
2022-06-27T15:48:47.764641+08:00 [debug] 116.3.197.73:51217 [WebHook] Send to: "/mqttauth/webhook/advance", params: {"username":"test","reason":"tcp_closed","node":"emqx_c01@127.0.0.1","disconnected_at":1656316127764,"connected_at":1656315716105,"clientid":"iedu_9161a7851","action":"client_disconnected"}
2022-06-27T15:48:48.031005+08:00 [info] 116.3.197.73:51217     msg: terminate
    reason: {shutdown,tcp_closed}
2022-06-27T15:48:48.031320+08:00 [debug] 116.3.197.73:52592     action: discard
    msg: session_already_shutdown
    pid: <0.282.13>

wangscaler · 2022 年6 月 28 日 09:17

应该是版本问题。他说的v4.4.5 ，你的4.4.1

heeejianbo · 2022 年6 月 30 日 08:17

一个零时的解决方法是，忽略 disconnect 事件中错误原因为 discarded , takeovered 的事件即可。这两个原因都是由于同名客户端被踢出导致的

这里指的是，client.disconnected 事件（即发到你服务器的 action=client_disconnected 的 HTTP 请求）里面的 Body 有个 reason 字段，可以看到 discarded 和 taokovered