gRPC Client出现各种花式超时和错误!

环境信息

  • EMQX 版本:
sysdescr  : EMQ X Broker
version   : 4.3.5
uptime    : 1 days, 18 hours, 15 minutes, 11 seconds
datetime  : 2022-07-13 08:38:16
  • 操作系统及版本:
Linux web20210629 4.18.0-193.6.3.el8_2.x86_64 #1 SMP Wed Jun 10 11:09:32 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
NAME="CentOS Linux"
VERSION="8 (Core)"
ID="centos"
ID_LIKE="rhel fedora"
VERSION_ID="8"
PLATFORM_ID="platform:el8"
PRETTY_NAME="CentOS Linux 8 (Core)"
ANSI_COLOR="0;31"
CPE_NAME="cpe:/o:centos:centos:8"
HOME_URL="https://www.centos.org/"
BUG_REPORT_URL="https://bugs.centos.org/"

CENTOS_MANTISBT_PROJECT="CentOS-8"
CENTOS_MANTISBT_PROJECT_VERSION="8"
REDHAT_SUPPORT_PRODUCT="centos"
REDHAT_SUPPORT_PRODUCT_VERSION="8"
  • 其他

问题描述

上线后,发现日志频繁出现超时警告和连接关闭错误,详见日志文件。请问如何处理?
以下是部分日志截取

2022-07-11T14:21:36.467907+08:00 [error] wt2000_868739059844955@117.132.191.211:56037 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_session_discarded(#{clientinfo => #{anonymous => false,clientid => <<"wt2000_868739059844955">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"emqx@127.0.0.1">>,password => <<>>,peerhost => <<"117.132.191.211">>,protocol => <<"mqtt">>,sockport => 1883,username => <<"debug">>}}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.1793.0>,{read,#Ref<0.3152732276.3586654212.166238>,1657520496467},5000]}
2022-07-11T14:21:36.467880+08:00 [error] wt2000_868739059843114@39.144.17.19:2067 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_session_created(#{clientinfo => #{anonymous => false,clientid => <<"wt2000_868739059843114">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"emqx@127.0.0.1">>,password => <<>>,peerhost => <<"39.144.17.19">>,protocol => <<"mqtt">>,sockport => 1883,username => <<"debug">>}}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.1793.0>,{read,#Ref<0.3152732276.3586654212.166233>,1657520496467},5000]}
2022-07-11T14:21:36.468036+08:00 [error] wt2000_868739059844955@39.144.8.168:13581 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_session_created(#{clientinfo => #{anonymous => false,clientid => <<"wt2000_868739059844955">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"emqx@127.0.0.1">>,password => <<>>,peerhost => <<"39.144.8.168">>,protocol => <<"mqtt">>,sockport => 1883,username => <<"debug">>}}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.1793.0>,{read,#Ref<0.3152732276.3586654212.166239>,1657520496467},5000]}
2022-07-11T14:21:36.468153+08:00 [error] wt2000_868739059843114@39.144.12.59:60278 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_session_discarded(#{clientinfo => #{anonymous => false,clientid => <<"wt2000_868739059843114">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"emqx@127.0.0.1">>,password => <<>>,peerhost => <<"39.144.12.59">>,protocol => <<"mqtt">>,sockport => 1883,username => <<"debug">>}}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.1796.0>,{read,#Ref<0.3152732276.3586654212.166244>,1657520496467},5000]}
2022-07-12T14:45:28.889583+08:00 [error] [gRPC Client] Stream shutdown reason: {stream_error,cancel,'Stream reset by server.'}, stream: #stream{st={open,idle}, buff_size=0, mqueue=[]}
2022-07-12T14:45:28.889648+08:00 [error] [gRPC Client] Stream shutdown reason: {stream_error,cancel,'Stream reset by server.'}, stream: #stream{st={open,idle}, buff_size=0, mqueue=[]}
2022-07-12T14:45:28.889711+08:00 [error] [gRPC Client] Stream shutdown reason: {stream_error,cancel,'Stream reset by server.'}, stream: #stream{st={open,idle}, buff_size=0, mqueue=[]}
2022-07-12T16:27:08.705864+08:00 [warning] wt2000_863488059425838@39.144.15.99:17948 [Channel] The PUBACK PacketId 2 is not found.
2022-07-12T16:27:08.706013+08:00 [warning] wt2000_863488059425838@39.144.15.99:17948 [Channel] The PUBACK PacketId 2 is not found.
2022-07-12T19:26:54.913511+08:00 [warning] wt2000_
OK@39.144.12.156:3983 [Channel] Client wt2000_, OK (Username: 'undefined') login failed for not_authorized
2022-07-12T20:19:39.339090+08:00 [warning] wt2000_868739059865521@39.144.16.239:26364 [Channel] The PUBACK PacketId 2 is not found.
2022-07-12T20:19:39.339212+08:00 [warning] wt2000_868739059865521@39.144.16.239:26364 [Channel] The PUBACK PacketId 2 is not found.
2022-07-12T21:38:40.315173+08:00 [warning] wt2000_863488055994514@221.178.127.180:50032 [Channel] The PUBACK PacketId 2 is not found.
2022-07-12T21:38:40.315310+08:00 [warning] wt2000_863488055994514@221.178.127.180:50032 [Channel] The PUBACK PacketId 2 is not found.

配置文件及日志

emqx.log.zip (182.5 KB)

有两种可能:
1 你的业务量比较大,已经超出grpc的性能太多,client处理不过来了。
2 外部的服务响应速度不够,第二部分的日志是服务端主动断开了emqx的grpc client,但是断开的原因要到外部服务端看。
查看EMQX性能的命令:

./emqx remote_console

进入EMQX控制台后,输入

observer_cli:start().

看下EMQX的htop输出,主要是看MsgQueue堆积的情况

进入控制台后,怎么操作去看不同的信息?

可以看到控制台上最下面有操作指引的。可以看到对的queue,memory,排列。

比如下面有个F/B进行翻页,我按Ctrl+F、Ctrl+B没有效果,Shift+f、Shift+B也没效果

按F后回车