feat: implement log throttling #12520

SergeTupchiy · 2024-02-15T16:44:43Z

Fixes EMQX-11530

Release version: v/e5.6.0

Short demo:
3000 subscribers to EMQX Enterprise with the default trial license:
emqtt_bench sub -t t/test -p 1883 -c 3000 -R 1000

2024-02-20T13:15:20.890612+02:00 [error] msg: connection_rejected_due_to_license_limit_reached, mfa: emqx_license:check/2(90), peername: 127.0.0.1:39654
2024-02-20T13:15:25.359433+02:00 [warning] msg: alarm_is_activated, mfa: emqx_alarm:do_actions/3(416), message: <<"License: live connection number exceeds 80%">>, name: license_quota
2024-02-20T13:16:05.176869+02:00 [warning] msg: log_events_throttled_during_last_period, mfa: emqx_log_throttler:maybe_log_dropped/2(141), period: 1 minutes, 0 seconds, dropped: #{"connection_rejected_due_to_license_limit_reached" => 2970}

Summary

PR Checklist

Please convert it to a draft if any of the following conditions are not met. Reviewers may skip over until all the items are checked:

Added tests for the changes
Added property-based tests for code which performs user input validation
Changed lines covered in coverage report
Change log has been added to changes/(ce|ee)/(feat|perf|fix|breaking)-<PR-id>.en.md files
For internal contributor: there is a jira ticket to track this change
Created PR to emqx-docs if documentation update is required, or link to a follow-up jira ticket
Schema changes are backward compatible

Checklist for CI (.github/workflows) changes

If changed package build workflow, pass this action (manual trigger)
Change log has been added to changes/ dir for user-facing artifacts update

SergeTupchiy · 2024-02-15T16:54:19Z

apps/emqx/src/emqx_log_throttler.erl

+            %% TODO: this still can flood the logs until throttle seq is created,
+            %% Alternatively we can register all the throttle IDs in init/1,
+            %% but this would require gathering all the throttle Ids somehow...
+            create(EventId),


This make throttling not very strict: it can pass some log events before the gen_server creates the sequence.
Though it's probably acceptable I have some ideas how to avoid it completely:

Change throttling API, instead of allow/1 implement log/3,4, e.g.:

log(EventId, Level, Data, Meta) when is_atom(EventId) -> Seq = persistent_term:get(?SEQ_ID(EventId), undefined), case Seq of undefined -> %% TODO: this still can flood the logs until throttle seq is created, %% Alternatively we can register all the throttle IDs in init/1, %% but this would require gathering all the throttle Ids somehow... create_and_maybe_log(EventId, Level, Data, Meta), SeqRef -> maybe_log(?IS_ALLOWED(SeqRef), Level, Data, Meta) end. handle_cast({create_maybe_log, EventId, Level, Data, Meta}, State) -> State1 = case State of #{EventId := _} -> %% Must be allready logged: increment counter and silently drop this event ?INC_SEQ(SeqRef), State; _ -> ?SLOG(Level, Data, Meta), SeqRef = ?NEW_SEQ, %% One event has been already occurred ?INC_SEQ(SeqRef), ok = ?NEW_THROTTLE(EventId, SeqRef), TimerRef = schedule_refresh(?WINDOW_TIME_SEC, EventId), State#{EventId => TimerRef} end, {noreply, State1};

Create sequences in init/1, but then we need to make sure every event_id used in ?LOG_THROTTLE somewhere in the code base has its sequence.

Maybe not a bad idea to maintain a static list of ids in a hidden config field's default value.
This makes it possible to configure the list.

Reworked to use a static list.

zmstone · 2024-02-16T07:11:23Z

apps/emqx_conf/src/emqx_conf_schema.erl

+                emqx_schema:duration_s(),
+                #{
+                    default => <<"1m">>,
+                    desc => ?DESC("log_throttling_window_time")


missing desc and label in rel/i18n/emqx_conf_schema.hocon

Fixed, thanks.

zmstone · 2024-02-16T07:11:48Z

apps/emqx_conf/src/emqx_conf_schema.erl

+                emqx_schema:duration_s(),
+                #{
+                    default => <<"1m">>,
+                    desc => ?DESC("log_throttling_window_time")


importance => ?IMPORTANCE_MEDIUM

apps/emqx/include/logger.hrl

zmstone · 2024-02-16T07:21:59Z

apps/emqx/src/emqx_log_throttler.erl

+            %% TODO: this still can flood the logs until throttle seq is created,
+            %% Alternatively we can register all the throttle IDs in init/1,
+            %% but this would require gathering all the throttle Ids somehow...
+            create(EventId),


Maybe not a bad idea to maintain a static list of ids in a hidden config field's default value.
This makes it possible to configure the list.

zmstone · 2024-02-20T09:25:28Z

apps/emqx/include/logger.hrl

+    ?SLOG_THROTTLE(EventId, Level, Data, #{})
+).
+
+-define(SLOG_THROTTLE(EventId, Level, Data, Meta),


Maybe just use the one-word msg as EventId ?
Otherwise it's duplicated as msg and as throttle_event_id

zmstone · 2024-02-20T09:28:39Z

apps/emqx_conf/src/emqx_conf_schema.erl

@@ -909,7 +909,12 @@ fields("log") ->
                    aliases => [file_handlers],
                    importance => ?IMPORTANCE_HIGH
                }
-            )}
+            )},
+        {"throttling",


Suggested change

{"throttling",

{throttling,

zmstone · 2024-02-20T09:29:22Z

apps/emqx/src/emqx_log_throttler.erl

+    ?SLOG(warning, #{
+        msg => "log_events_throttled_during_last_period",
+        throttle_event_id => EventId,
+        period_sec => Period,


duration => format_duration_string(Period),

zmstone · 2024-02-20T09:32:45Z

apps/emqx/src/emqx_log_throttler.erl

+handle_info(refresh, State) ->
+    PeriodSec = ?WINDOW_TIME_SEC,
+    EventIds = ?EVENT_IDS_LIST,
+    ok = lists:foreach(


maybe log a summary instead of one for each id?
e.g.
dropped => #{id1 => 12, id2 => 34}

zmstone · 2024-02-20T09:35:12Z

apps/emqx_conf/src/emqx_conf_schema.erl

+            )},
+        %% A static list of event ids used in ?SLOG_THROTTLE/3,4 macro.
+        %% For internal (developer) use only.
+        {"event_ids",


Suggested change

{"event_ids",

{msgs,

zmstone · 2024-02-20T09:36:14Z

apps/emqx_conf/src/emqx_conf_schema.erl

@@ -1012,6 +1017,34 @@ fields("log_burst_limit") ->
                }
            )}
    ];
+fields("log_throttling") ->
+    [
+        {"window_time",


use atoms for field names, also, should be time_window instead of window_time ?

Suggested change

{"window_time",

{time_window,

time_window also sounds more naturally to me, but there is window_time in logger burst_limit conf: https://github.com/emqx/emqx/blob/master/apps/emqx_conf/src/emqx_conf_schema.erl#L1006, so I decided to be consistent with it...

zmstone · 2024-02-20T09:37:32Z

rel/i18n/emqx_conf_schema.hocon

+dropping all but the first event within a configured time window."""
+
+log_throttling_window_time.desc:
+"""A time interval at which log throttling is applied. Defaults to 1 minute."""


no need to mention default value in desc, the schema dump generates default along side it.

Suggested change

"""A time interval at which log throttling is applied. Defaults to 1 minute."""

"""For throttled messages, only log 1 in each time window."""

zmstone · 2024-02-20T09:37:50Z

rel/i18n/emqx_conf_schema.hocon

+"""A time interval at which log throttling is applied. Defaults to 1 minute."""
+
+log_throttling_window_time.label:
+"""Log Throttling Window Time"""


Suggested change

"""Log Throttling Window Time"""

"""Log Throttling Time Window"""

thalesmg · 2024-03-04T17:04:16Z

apps/emqx_conf/src/emqx_conf_schema.erl

+    [
+        {time_window,
+            sc(
+                emqx_schema:duration_s(),


Nit: since this is used by send_after, might be safer to use timeout_duration_s.

Thanks @thalesmg, fixed: #12647

also updated emqx#12520 to include newly added throttled log id

savonarola · 2024-04-24T12:13:06Z

apps/emqx/include/logger.hrl

+).
+
+-define(SLOG_THROTTLE(Level, Data, Meta),
+    case emqx_log_throttler:allow(Level, maps:get(msg, Data)) of


Doesn't that make Data

evaluated twice

evaluated even if actual log level is above the passed Level?

Thanks, fixed: #12927

SergeTupchiy commented Feb 15, 2024

View reviewed changes

zmstone reviewed Feb 16, 2024

View reviewed changes

SergeTupchiy force-pushed the EMQX-11530-log-throttling branch 7 times, most recently from d4e908b to 9daac34 Compare February 19, 2024 19:30

SergeTupchiy marked this pull request as ready for review February 19, 2024 19:32

SergeTupchiy requested review from lafirest and a team as code owners February 19, 2024 19:32

SergeTupchiy force-pushed the EMQX-11530-log-throttling branch from 9daac34 to 5714bd5 Compare February 19, 2024 20:10

zmstone reviewed Feb 20, 2024

View reviewed changes

SergeTupchiy force-pushed the EMQX-11530-log-throttling branch 2 times, most recently from 0000b3c to 5864e99 Compare February 20, 2024 11:21

feat: implement log throttling

98ba300

SergeTupchiy force-pushed the EMQX-11530-log-throttling branch from 5864e99 to 7a1d173 Compare February 20, 2024 11:23

zmstone previously approved these changes Feb 20, 2024

View reviewed changes

feat: enable log throttling for potentially flooding log events

9bd0d1b

SergeTupchiy dismissed zmstone’s stale review via 9bd0d1b February 20, 2024 12:24

SergeTupchiy force-pushed the EMQX-11530-log-throttling branch from 7a1d173 to 9bd0d1b Compare February 20, 2024 12:24

zmstone approved these changes Feb 20, 2024

View reviewed changes

SergeTupchiy merged commit f725587 into emqx:master Feb 20, 2024
166 checks passed

thalesmg reviewed Mar 4, 2024

View reviewed changes

zmstone added a commit to zmstone/emqx that referenced this pull request Mar 20, 2024

docs: add change log for emqx#12746

efc126e

also updated emqx#12520 to include newly added throttled log id

zmstone added a commit to zmstone/emqx that referenced this pull request Mar 20, 2024

docs: add change log for emqx#12746

ef51adb

also updated emqx#12520 to include newly added throttled log id

zmstone added a commit to zmstone/emqx that referenced this pull request Mar 20, 2024

docs: add change log for emqx#12746

90fce21

also updated emqx#12520 to include newly added throttled log id

BrewTestBot mentioned this pull request Mar 28, 2024

emqx 5.6.0 Homebrew/homebrew-core#167392

Merged

savonarola reviewed Apr 24, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: implement log throttling #12520

feat: implement log throttling #12520

SergeTupchiy commented Feb 15, 2024 •

edited

SergeTupchiy Feb 15, 2024

zmstone Feb 16, 2024

SergeTupchiy Feb 16, 2024

zmstone Feb 16, 2024

SergeTupchiy Feb 16, 2024

zmstone Feb 16, 2024

SergeTupchiy Feb 16, 2024

zmstone Feb 16, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

SergeTupchiy Feb 20, 2024

zmstone Feb 20, 2024

zmstone Feb 20, 2024

thalesmg Mar 4, 2024

SergeTupchiy Mar 4, 2024

savonarola Apr 24, 2024 •

edited

SergeTupchiy Apr 24, 2024

	"""A time interval at which log throttling is applied. Defaults to 1 minute."""
	"""For throttled messages, only log 1 in each time window."""

	"""Log Throttling Window Time"""
	"""Log Throttling Time Window"""

feat: implement log throttling #12520

feat: implement log throttling #12520

Conversation

SergeTupchiy commented Feb 15, 2024 • edited

Summary

PR Checklist

Checklist for CI (.github/workflows) changes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

savonarola Apr 24, 2024 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

SergeTupchiy commented Feb 15, 2024 •

edited

savonarola Apr 24, 2024 •

edited