exhook插件超时

[wangscaler]

环境信息

• EMQX 版本：4.3.5
• 操作系统及版本：centos8
• 其他

问题描述

今天设备登录不上去了，发现日志里面提示连接exhook超时。从dashboard重启exhook插件之后恢复。
集群三台同时挂掉。

配置文件及日志

2022-07-22T10:34:58.209445+08:00 [error] 设备ID@IP:端口 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_client_authenticate(#{clientinfo => #{anonymous => true,clientid => <<"设备ID">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"节点名">>,password => <<"密码">>,peerhost => <<"IP地址">>,protocol => <<"mqtt">>,sockport => 端口,username => <<"用户名">>},result => false}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.2113.0>,{read,#Ref<0.2740969585.419692545.203380>,1658457298208},5000]}
2022-07-22T10:34:58.209661+08:00 [warning] 设备ID@IP地址:端口 [Channel] Client 设备ID(Username: '用户名') login failed for not_authorized

[heeejianbo]

看日志是 timeout 读 grpc 的返回超时了（5秒）
那段时间 emqx 或者 grpc 服务的压力很大么？

[wangscaler]

@heeejianbo

emqx 或者 grpc 服务的压力

压力不大，他们尝试连接了一天，一直是超时状态。
才让我排查问题，我一看是exhook超时。

[heeejianbo]

有全量的日志么，可以脱敏后发我邮箱 hejb@emqx.io

[heeejianbo]

光看这里 是没有更多的信息了

[wangscaler]

在emqx.log的日志里只有这些。没有更多的提示了。

[wangscaler]

2022-08-30T14:30:31.723640+08:00 [error] {error,“8”,<<154>>}@IP地址:端口 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_client_authenticate(#{clientinfo => #{anonymous => true,clientid => <<56,154>>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<“节点名”>>,password => <<“密码”>>,peerhost => <<“IP地址”>>,protocol => <<“mqtt”>>,sockport => 端口号,username => <<“用户名”>>},result => false}, #{channel => “default”}) throw an exception: badarg, stacktrace: [{erlang,byte_size,[{error,<<“8”>>,<<154>>}],},{emqx_exhook_pb,e_type_string,3,[{file,“emqx_exhook_pb.erl”},{line,1979}]},{emqx_exhook_pb,encode_msg_client_info,3,[{file,“emqx_exhook_pb.erl”},{line,1305}]},{emqx_exhook_pb,e_mfield_client_authenticate_request_clientinfo,3,[{file,“emqx_exhook_pb.erl”},{line,1717}]},{emqx_exhook_pb,encode_msg_client_authenticate_request,3,[{file,“emqx_exhook_pb.erl”},{line,550}]},{grpc_client,send,3,[{file,“grpc_client.erl”},{line,182}]},{grpc_client,unary,4,[{file,“grpc_client.erl”},{line,147}]},{emqx_exhook_server,do_call,3,[{file,“emqx_exhook_server.erl”},{line,272}]},{emqx_exhook,call_fold,4,[{file,“emqx_exhook.erl”},{line,96}]},{emqx_exhook_handler,on_client_authenticate,2,[{file,“emqx_exhook_handler.erl”},{line,103}]},{emqx_hooks,safe_execute,2,[{file,“emqx_hooks.erl”},{line,191}]},{emqx_hooks,do_run_fold,3,[{file,[…]},{line,…}]},{emqx_access_control,authenticate,1,[{file,…},{…}]},{emqx_channel,auth_connect,2,[{…}|…]},{emqx_misc,pipeline,3,[…]},{emqx_channel,handle_in,2,…}]

貌似是参数异常导致的。是不是没做异常处理4.3.5版本

不知道设备连接的clientid是啥，看日志应该是解析这个字段异常了。

[heeejianbo]

看着像是非 utf-8 的 clientid 到 protobuff 的编码失败了

https://developers.google.com/protocol-buffers/docs/proto

Protobuff 规范中 string 必须是 utf8 字符串才行的

[wangscaler]

我知道这个clientId肯定是不合法的，正常情况也不会有。但是总不能因为他的不合法，导致插件失效，从而影响其他设备吧。

[heeejianbo]

这个报错应该只会影响这个这个客户端的本次请求，不会导致整个插件不可用才对

[wangscaler]

昨天说是插件挂了，重启插件之后接着又挂了。看日志就这台设备一直重连报错。他们找到这台仪器关机之后就好了。
重启插件之后，我用MQTT测试可以，但是那个设备连接之后，就一直等待。过一会日志才会出插件超时。

[heeejianbo]

可能是由于这个报错导致了 有太多 grpc stream 没有被及时关闭 然后后续的请求 被 grpc 服务器端的 stream最大并发数 给限制了

但这只是一个猜测，方便发下全量的日志么，尤其是 插件挂了 其他设备也被影响 这部分的，

[wangscaler]

2022-08-30T15:14:37.351831+08:00 [warning] [gRPC Client] 
Unknown stream ref: {stop,{goaway,15,enhance_your_calm,<<"too_many_pings">>},'Client is going away.'}, event: {gun_error,<0.10063.2547>,{stop,{goaway,15,enhance_your_calm,<<"too_many_pings">>},'Client is going away.'}}


2022-08-30T15:14:50.527550+08:00 [error] 
设备clientId1@设备1的IP地址:8634 [ExHook Svr] CALL emqx_exhook_v_1_hook_provider_client:on_client_authenticate(#{clientinfo => #{anonymous => true,clientid => <<"设备clientId1">>,cn => <<>>,dn => <<>>,is_superuser => false,mountpoint => <<>>,node => <<"节点1">>,password => <<"设备密码">>,peerhost => <<"设备1的IP地址">>,protocol => <<"mqtt">>,sockport => 11885,username => <<"某台设备的用户名">>},result => false}, #{channel => "default"}) throw an exception: timeout, stacktrace: {gen_server,call,[<0.25232.2549>,{read,#Ref<0.291532261.2088501249.43701>,1661843690526},5000]}


2022-08-30T15:14:50.527877+08:00 [warning]
 设备clientId1@设备1的IP地址:8634 [Channel] Client 设备clientId1 (Username: '某台设备的用户名') login failed for not_authorized

[wangscaler]

grpc设置了10个线程，当这个clientid连接10次占满之后，就进不来了，怎么释放这个线程？

[iamfuture_x]

问题解决了么