From 1fefb421bc44e6a59dbc8ece6b4cdf29822dcb58 Mon Sep 17 00:00:00 2001 From: firest Date: Fri, 10 May 2024 15:34:11 +0800 Subject: [PATCH 1/3] feat(limiter): lift the log level of rate limiter to `warning` --- apps/emqx/src/emqx_connection.erl | 38 +++++++++++++++++-------- apps/emqx/src/emqx_ws_connection.erl | 38 +++++++++++++++++-------- apps/emqx_conf/src/emqx_conf_schema.erl | 3 +- 3 files changed, 54 insertions(+), 25 deletions(-) diff --git a/apps/emqx/src/emqx_connection.erl b/apps/emqx/src/emqx_connection.erl index f115ad216..80046ca5d 100644 --- a/apps/emqx/src/emqx_connection.erl +++ b/apps/emqx/src/emqx_connection.erl @@ -1013,17 +1013,24 @@ check_limiter( Data, WhenOk, Msgs, - #state{limiter_timer = undefined, limiter = Limiter} = State + #state{channel = Channel, limiter_timer = undefined, limiter = Limiter} = State ) -> case emqx_limiter_container:check_list(Needs, Limiter) of {ok, Limiter2} -> WhenOk(Data, Msgs, State#state{limiter = Limiter2}); {pause, Time, Limiter2} -> - ?SLOG(debug, #{ - msg => "pause_time_due_to_rate_limit", - needs => Needs, - time_in_ms => Time - }), + ?SLOG_THROTTLE( + warning, + #{ + msg => pause_time_due_to_rate_limit, + needs => Needs, + time_in_ms => Time + }, + #{ + tag => "RATE", + clientid => emqx_channel:info(clientid, Channel) + } + ), Retry = #retry{ types = [Type || {_, Type} <- Needs], @@ -1057,7 +1064,7 @@ check_limiter( %% try to perform a retry -spec retry_limiter(state()) -> _. -retry_limiter(#state{limiter = Limiter} = State) -> +retry_limiter(#state{channel = Channel, limiter = Limiter} = State) -> #retry{types = Types, data = Data, next = Next} = emqx_limiter_container:get_retry_context(Limiter), case emqx_limiter_container:retry_list(Types, Limiter) of @@ -1071,11 +1078,18 @@ retry_limiter(#state{limiter = Limiter} = State) -> } ); {pause, Time, Limiter2} -> - ?SLOG(debug, #{ - msg => "pause_time_due_to_rate_limit", - types => Types, - time_in_ms => Time - }), + ?SLOG_THROTTLE( + warning, + #{ + msg => pause_time_due_to_rate_limit, + types => Types, + time_in_ms => Time + }, + #{ + tag => "RATE", + clientid => emqx_channel:info(clientid, Channel) + } + ), TRef = start_timer(Time, limit_timeout), diff --git a/apps/emqx/src/emqx_ws_connection.erl b/apps/emqx/src/emqx_ws_connection.erl index ea4c89321..f12e76821 100644 --- a/apps/emqx/src/emqx_ws_connection.erl +++ b/apps/emqx/src/emqx_ws_connection.erl @@ -600,17 +600,24 @@ check_limiter( Data, WhenOk, Msgs, - #state{limiter_timer = undefined, limiter = Limiter} = State + #state{channel = Channel, limiter_timer = undefined, limiter = Limiter} = State ) -> case emqx_limiter_container:check_list(Needs, Limiter) of {ok, Limiter2} -> WhenOk(Data, Msgs, State#state{limiter = Limiter2}); {pause, Time, Limiter2} -> - ?SLOG(debug, #{ - msg => "pause_time_due_to_rate_limit", - needs => Needs, - time_in_ms => Time - }), + ?SLOG_THROTTLE( + warning, + #{ + msg => pause_time_due_to_rate_limit, + needs => Needs, + time_in_ms => Time + }, + #{ + tag => "RATE", + clientid => emqx_channel:info(clientid, Channel) + } + ), Retry = #retry{ types = [Type || {_, Type} <- Needs], @@ -644,7 +651,7 @@ check_limiter( State#state{limiter_buffer = queue:in(New, Buffer)}. -spec retry_limiter(state()) -> state(). -retry_limiter(#state{limiter = Limiter} = State) -> +retry_limiter(#state{channel = Channel, limiter = Limiter} = State) -> #retry{types = Types, data = Data, next = Next} = emqx_limiter_container:get_retry_context( Limiter ), @@ -659,11 +666,18 @@ retry_limiter(#state{limiter = Limiter} = State) -> } ); {pause, Time, Limiter2} -> - ?SLOG(debug, #{ - msg => "pause_time_due_to_rate_limit", - types => Types, - time_in_ms => Time - }), + ?SLOG_THROTTLE( + warning, + #{ + msg => pause_time_due_to_rate_limit, + types => Types, + time_in_ms => Time + }, + #{ + tag => "RATE", + clientid => emqx_channel:info(clientid, Channel) + } + ), TRef = start_timer(Time, limit_timeout), diff --git a/apps/emqx_conf/src/emqx_conf_schema.erl b/apps/emqx_conf/src/emqx_conf_schema.erl index 262c517e8..3a2d86694 100644 --- a/apps/emqx_conf/src/emqx_conf_schema.erl +++ b/apps/emqx_conf/src/emqx_conf_schema.erl @@ -84,7 +84,8 @@ cannot_publish_to_topic_due_to_not_authorized, cannot_publish_to_topic_due_to_quota_exceeded, connection_rejected_due_to_license_limit_reached, - dropped_msg_due_to_mqueue_is_full + dropped_msg_due_to_mqueue_is_full, + pause_time_due_to_rate_limit ]). %% Callback to upgrade config after loaded from config file but before validation. From bd7ccc354691378344b04d7b0ee925e726deaff8 Mon Sep 17 00:00:00 2001 From: firest Date: Fri, 10 May 2024 18:48:51 +0800 Subject: [PATCH 2/3] chore: update change --- changes/ce/feat-13009.en.md | 1 + 1 file changed, 1 insertion(+) create mode 100644 changes/ce/feat-13009.en.md diff --git a/changes/ce/feat-13009.en.md b/changes/ce/feat-13009.en.md new file mode 100644 index 000000000..175ea8c51 --- /dev/null +++ b/changes/ce/feat-13009.en.md @@ -0,0 +1 @@ +Lifted the log level of rate limiter to `warning`. From 7a7bd84cba9ee9f1786c421de60f43c5da651a83 Mon Sep 17 00:00:00 2001 From: firest Date: Tue, 14 May 2024 15:34:13 +0800 Subject: [PATCH 3/3] fix(limiter): improved log content --- apps/emqx/src/emqx_connection.erl | 10 ++++------ apps/emqx/src/emqx_ws_connection.erl | 10 ++++------ apps/emqx_conf/src/emqx_conf_schema.erl | 2 +- changes/ce/feat-13009.en.md | 2 +- 4 files changed, 10 insertions(+), 14 deletions(-) diff --git a/apps/emqx/src/emqx_connection.erl b/apps/emqx/src/emqx_connection.erl index 80046ca5d..3363d62f9 100644 --- a/apps/emqx/src/emqx_connection.erl +++ b/apps/emqx/src/emqx_connection.erl @@ -1022,9 +1022,8 @@ check_limiter( ?SLOG_THROTTLE( warning, #{ - msg => pause_time_due_to_rate_limit, - needs => Needs, - time_in_ms => Time + msg => socket_receive_paused_by_rate_limit, + paused_ms => Time }, #{ tag => "RATE", @@ -1081,9 +1080,8 @@ retry_limiter(#state{channel = Channel, limiter = Limiter} = State) -> ?SLOG_THROTTLE( warning, #{ - msg => pause_time_due_to_rate_limit, - types => Types, - time_in_ms => Time + msg => socket_receive_paused_by_rate_limit, + paused_ms => Time }, #{ tag => "RATE", diff --git a/apps/emqx/src/emqx_ws_connection.erl b/apps/emqx/src/emqx_ws_connection.erl index f12e76821..7c6f3598c 100644 --- a/apps/emqx/src/emqx_ws_connection.erl +++ b/apps/emqx/src/emqx_ws_connection.erl @@ -609,9 +609,8 @@ check_limiter( ?SLOG_THROTTLE( warning, #{ - msg => pause_time_due_to_rate_limit, - needs => Needs, - time_in_ms => Time + msg => socket_receive_paused_by_rate_limit, + paused_ms => Time }, #{ tag => "RATE", @@ -669,9 +668,8 @@ retry_limiter(#state{channel = Channel, limiter = Limiter} = State) -> ?SLOG_THROTTLE( warning, #{ - msg => pause_time_due_to_rate_limit, - types => Types, - time_in_ms => Time + msg => socket_receive_paused_by_rate_limit, + paused_ms => Time }, #{ tag => "RATE", diff --git a/apps/emqx_conf/src/emqx_conf_schema.erl b/apps/emqx_conf/src/emqx_conf_schema.erl index 3a2d86694..9b7277e34 100644 --- a/apps/emqx_conf/src/emqx_conf_schema.erl +++ b/apps/emqx_conf/src/emqx_conf_schema.erl @@ -85,7 +85,7 @@ cannot_publish_to_topic_due_to_quota_exceeded, connection_rejected_due_to_license_limit_reached, dropped_msg_due_to_mqueue_is_full, - pause_time_due_to_rate_limit + socket_receive_paused_by_rate_limit ]). %% Callback to upgrade config after loaded from config file but before validation. diff --git a/changes/ce/feat-13009.en.md b/changes/ce/feat-13009.en.md index 175ea8c51..fe90eeb15 100644 --- a/changes/ce/feat-13009.en.md +++ b/changes/ce/feat-13009.en.md @@ -1 +1 @@ -Lifted the log level of rate limiter to `warning`. +Changed the log level of message receive pause from `debug` to `warning`. The log message `socket_receive_paused_by_rate_limit` is throttled to avoid excessive logging.