From 5b48b06d4a2178b474561ca070f0dccd9fb88be0 Mon Sep 17 00:00:00 2001 From: Serge Tupchii Date: Mon, 26 Feb 2024 14:17:36 +0200 Subject: [PATCH 1/2] fix: trace throttled log events --- apps/emqx/include/logger.hrl | 13 +++++++++---- apps/emqx/src/emqx_trace/emqx_trace_formatter.erl | 4 +++- 2 files changed, 12 insertions(+), 5 deletions(-) diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl index 59285e9d5..313358bcd 100644 --- a/apps/emqx/include/logger.hrl +++ b/apps/emqx/include/logger.hrl @@ -51,7 +51,7 @@ true -> ?SLOG(Level, Data, Meta); false -> - ok + ?_DO_TRACE(Level, maps:get(msg, Data), maps:merge(Data, Meta)) end ). @@ -61,8 +61,8 @@ -define(TRACE(Tag, Msg, Meta), ?TRACE(debug, Tag, Msg, Meta)). -%% Only evaluate when necessary --define(TRACE(Level, Tag, Msg, Meta), begin +%% Internal macro +-define(_DO_TRACE(Tag, Msg, Meta), case persistent_term:get(?TRACE_FILTER, []) of [] -> ok; %% We can't bind filter list to a variable because we pollute the calling scope with it. @@ -70,7 +70,12 @@ %% because this adds overhead to the happy path. %% So evaluate `persistent_term:get` twice. _ -> emqx_trace:log(persistent_term:get(?TRACE_FILTER, []), Msg, (Meta)#{trace_tag => Tag}) - end, + end +). + +%% Only evaluate when necessary +-define(TRACE(Level, Tag, Msg, Meta), begin + ?_DO_TRACE(Tag, Msg, Meta), ?SLOG( Level, (emqx_trace_formatter:format_meta_map(Meta))#{msg => Msg, tag => Tag}, diff --git a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl index 4dd22966b..6cbcc0510 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl @@ -35,7 +35,9 @@ format( ClientId = to_iolist(maps:get(clientid, Meta, "")), Peername = maps:get(peername, Meta, ""), MetaBin = format_meta(Meta, PEncode), - [Time, " [", Tag, "] ", ClientId, "@", Peername, " msg: ", Msg, ", ", MetaBin, "\n"]; + Msg1 = to_iolist(Msg), + Tag1 = to_iolist(Tag), + [Time, " [", Tag1, "] ", ClientId, "@", Peername, " msg: ", Msg1, ", ", MetaBin, "\n"]; format(Event, Config) -> emqx_logger_textfmt:format(Event, Config). From 5d4c85cd84644000fd69e92fa876471908e91a39 Mon Sep 17 00:00:00 2001 From: Serge Tupchii Date: Mon, 26 Feb 2024 14:18:46 +0200 Subject: [PATCH 2/2] chore: list throttled log events in the change-log --- apps/emqx/include/logger.hrl | 4 ++-- changes/ce/feat-12520.en.md | 6 ++++++ 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl index 313358bcd..8974eace4 100644 --- a/apps/emqx/include/logger.hrl +++ b/apps/emqx/include/logger.hrl @@ -59,8 +59,6 @@ -define(TRACE_FILTER, emqx_trace_filter). -define(OWN_KEYS, [level, filters, filter_default, handlers]). --define(TRACE(Tag, Msg, Meta), ?TRACE(debug, Tag, Msg, Meta)). - %% Internal macro -define(_DO_TRACE(Tag, Msg, Meta), case persistent_term:get(?TRACE_FILTER, []) of @@ -73,6 +71,8 @@ end ). +-define(TRACE(Tag, Msg, Meta), ?TRACE(debug, Tag, Msg, Meta)). + %% Only evaluate when necessary -define(TRACE(Level, Tag, Msg, Meta), begin ?_DO_TRACE(Tag, Msg, Meta), diff --git a/changes/ce/feat-12520.en.md b/changes/ce/feat-12520.en.md index 593b66ec4..99d29fb2e 100644 --- a/changes/ce/feat-12520.en.md +++ b/changes/ce/feat-12520.en.md @@ -1,2 +1,8 @@ Implement log throttling. The feature reduces the number of potentially flooding logged events by dropping all but the first event within a configured time window. +Throttling is applied to the following log events: + - authorization_permission_denied, + - 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.