exproto StartTimer异常

错误报告

环境

  • EMQX 版本:开源版4.3.5
  • 操作系统版本:centos8

重现此问题的步骤

开始的做法时,设备初次连接的时候,使用

timer = exproto_pb2.TimerRequest(conn=request.conn, type=exproto_pb2.TimerType.KEEPALIVE, interval=120)
response = self.stub.StartTimer(timer)

启动定时器将120*3s不发消息的设备踢掉。
我的设备是1分钟一条数据,但是当第四分钟数据收到解析完毕之后,通过

publish = exproto_pb2.PublishRequest(
  conn=request.conn,
  topic="/$sys/username/clientId/upload",
  qos=1, 
  payload=json.dumps(data).encode("utf-8")
 ) 
self.stub.Publish(publish)

发布的时候,会出现异常,显示

2023-03-03 15:59:00,588 ERROR:root:OnReceivedBytes
2023-03-03 15:59:00,588 ERROR:root:<_InactiveRpcError of RPC that terminated with:
status = StatusCode.UNAVAILABLE
details = "Socket closed"
debug_error_string = "{"created":"@1677830340.588034111","description":"Error received from peer ipv4:127.0.0.1:9100","file":"src/core/lib/surface/call.cc","file_line":1069,"grpc_message":"Socket closed","grpc_status":14}

看着像是连接关闭了,但是之后设备数据都是正常的,每4分钟出现一次这个异常,数据丢失。
我怀疑跟定时器有关,所以修改代码为每次发布完重新启动一次定时器,然后发现异常不再出现了。

预期行为

根据我之前的测试结果,这个定时器在设备链接上来,启动一次。当每次收到设备信息的时候,会重新刷新定时器的时间,所以根本不用我每次发布之后,重新使用定时器手动刷新。

实际行为

实际上,我使用其他的tcp连接工具进行测试的时候,也是正常的,但不知道为什么会出现这种异常,具体的原因没有找到。



其他

感谢反馈 :rainbow: !看起来很有可能是 EMQX 定时器这里的 BUG,方便给下 EMQX 相关于这个设备的所有 DEBUG 日志么?

没有使用debug模式记录日志


2023-03-03T16:15:00.453895+08:00 [error] [ExProto gClient] Send to on_received_bytes method failure, request: #{bytes => <<"##0271QN=20230303161500000;ST=22;CN=2011;PW=456789;MN=mn;Fla"...>>,conn => <<"g1hkABdlbXF4QHp5dGVjaC5kb21haW4zLmNvbQAAFqwAAB+QAAAAAQ==">>}, stacktrace: [{grpc_client,send,3,[{file,"grpc_client.erl"},{line,185}]},{emqx_exproto_gcli,handle_cast,2,[{file,"emqx_exproto_gcli.erl"},{line,90}]},{gen_server,try_dispatch,4,[{file,"gen_server.erl"},{line,689}]},{gen_server,handle_msg,6,[{file,"gen_server.erl"},{line,765}]},{proc_lib,init_p_do_apply,3,[{file,"proc_lib.erl"},{line,226}]}]
2023-03-03T16:15:00.454236+08:00 [error] supervisor: 'esockd_connection_sup - <0.32434.8079>', errorContext: connection_shutdown, reason: {error,{on_received_bytes,not_found}}, offender: [{pid,<0.5804.8080>},{name,connection},{mfargs,{emqx_exproto_conn,start_link,[[{handler,'protoname:tcp'},{active_n,100},{idle_timeout,360000},{max_conn_rate,1000}]]}}]

能看到一些错误日志。

这行日志看起来是 gRPC 客户端在发生这个请求到你的 gRPC 服务时,出现了错误然后就直接断开了,然后引起了你的客户端连接也断开了

客户端好像是没断开,没看到设备重新上线的回调。下一包数据还能正常入库。