feat: add authentication_failure throttled log

also included changes:

1. add 'username' to log metadata
2. add 'tag' to authz warning logs

apps/emqx/src/emqx_access_control.erl

@@ -154,7 +154,7 @@ do_authorize(ClientInfo, Action, Topic) ->
     case run_hooks('client.authorize', [ClientInfo, Action, Topic], Default) of
         AuthzResult = #{result := Result} when Result == allow; Result == deny ->
             From = maps:get(from, AuthzResult, unknown),
-            ok = log_result(ClientInfo, Topic, Action, From, Result),
+            ok = log_result(Topic, Action, From, Result),
             emqx_hooks:run(
                 'client.check_authz_complete',
                 [ClientInfo, Action, Topic, Result, From]
@@ -173,24 +173,28 @@ do_authorize(ClientInfo, Action, Topic) ->
             deny
     end.
 
-log_result(#{username := Username}, Topic, Action, From, Result) ->
+log_result(Topic, Action, From, Result) ->
     LogMeta = fun() ->
         #{
-            username => Username,
             topic => Topic,
             action => format_action(Action),
             source => format_from(From)
         }
     end,
-    case Result of
-        allow ->
-            ?SLOG(info, (LogMeta())#{msg => "authorization_permission_allowed"});
-        deny ->
+    do_log_result(Action, Result, LogMeta).
+
+do_log_result(_Action, allow, LogMeta) ->
+    ?SLOG(info, (LogMeta())#{msg => "authorization_permission_allowed"}, #{tag => "AUTHZ"});
+do_log_result(?AUTHZ_PUBLISH_MATCH_MAP(_, _), deny, LogMeta) ->
+    %% for publish action, we do not log permission deny at warning level here
+    %% because it will be logged as cannot_publish_to_topic_due_to_not_authorized
+    ?SLOG(info, (LogMeta())#{msg => "authorization_permission_denied"}, #{tag => "AUTHZ"});
+do_log_result(_, deny, LogMeta) ->
     ?SLOG_THROTTLE(
         warning,
-                (LogMeta())#{msg => authorization_permission_denied}
-            )
-    end.
+        (LogMeta())#{msg => authorization_permission_denied},
+        #{tag => "AUTHZ"}
+    ).
 
 %% @private Format authorization rules source.
 format_from(default) ->

apps/emqx/src/emqx_channel.erl

@@ -633,7 +633,7 @@ process_publish(Packet = ?PUBLISH_PACKET(QoS, Topic, PacketId), Channel) ->
                     msg => cannot_publish_to_topic_due_to_not_authorized,
                     reason => emqx_reason_codes:name(Rc)
                 },
-                #{topic => Topic}
+                #{topic => Topic, tag => "AUTHZ"}
             ),
             case emqx:get_config([authorization, deny_action], ignore) of
                 ignore ->
@@ -652,7 +652,7 @@ process_publish(Packet = ?PUBLISH_PACKET(QoS, Topic, PacketId), Channel) ->
                     msg => cannot_publish_to_topic_due_to_quota_exceeded,
                     reason => emqx_reason_codes:name(Rc)
                 },
-                #{topic => Topic}
+                #{topic => Topic, tag => "AUTHZ"}
             ),
             case QoS of
                 ?QOS_0 ->
@@ -1612,8 +1612,10 @@ fix_mountpoint(_ConnPkt, ClientInfo = #{mountpoint := MountPoint}) ->
 %%--------------------------------------------------------------------
 %% Set log metadata
 
-set_log_meta(_ConnPkt, #channel{clientinfo = #{clientid := ClientId}}) ->
-    emqx_logger:set_metadata_clientid(ClientId).
+set_log_meta(_ConnPkt, #channel{clientinfo = #{clientid := ClientId} = ClientInfo}) ->
+    Username = maps:get(username, ClientInfo, undefined),
+    emqx_logger:set_metadata_clientid(ClientId),
+    emqx_logger:set_metadata_username(Username).
 
 %%--------------------------------------------------------------------
 %% Check banned
@@ -1680,6 +1682,7 @@ authenticate(
                 Channel
             );
         _ ->
+            log_auth_failure("bad_authentication_method"),
             {error, ?RC_BAD_AUTHENTICATION_METHOD}
     end.
 
@@ -1706,6 +1709,7 @@ do_authenticate(
                 auth_cache = AuthCache
             }};
         {error, Reason} ->
+            log_auth_failure(Reason),
             {error, emqx_reason_codes:connack_error(Reason)}
     end;
 do_authenticate(Credential, #channel{clientinfo = ClientInfo} = Channel) ->
@@ -1713,9 +1717,20 @@ do_authenticate(Credential, #channel{clientinfo = ClientInfo} = Channel) ->
         {ok, AuthResult} ->
             {ok, #{}, Channel#channel{clientinfo = merge_auth_result(ClientInfo, AuthResult)}};
         {error, Reason} ->
+            log_auth_failure(Reason),
             {error, emqx_reason_codes:connack_error(Reason)}
     end.
 
+log_auth_failure(Reason) ->
+    ?SLOG_THROTTLE(
+        warning,
+        #{
+            msg => authentication_failure,
+            reason => Reason
+        },
+        #{tag => "AUTHN"}
+    ).
+
 merge_auth_result(ClientInfo, AuthResult) when is_map(ClientInfo) andalso is_map(AuthResult) ->
     IsSuperuser = maps:get(is_superuser, AuthResult, false),
     maps:merge(ClientInfo, AuthResult#{is_superuser => IsSuperuser}).

apps/emqx/src/emqx_logger.erl

@@ -43,6 +43,7 @@
 -export([
     set_metadata_peername/1,
     set_metadata_clientid/1,
+    set_metadata_username/1,
     set_proc_metadata/1,
     set_primary_log_level/1,
     set_log_handler_level/2,
@@ -142,6 +143,12 @@ set_metadata_clientid(<<>>) ->
 set_metadata_clientid(ClientId) ->
     set_proc_metadata(#{clientid => ClientId}).
 
+-spec set_metadata_username(emqx_types:username()) -> ok.
+set_metadata_username(Username) when Username =:= undefined orelse Username =:= <<>> ->
+    ok;
+set_metadata_username(Username) ->
+    set_proc_metadata(#{username => Username}).
+
 -spec set_metadata_peername(peername_str()) -> ok.
 set_metadata_peername(Peername) ->
     set_proc_metadata(#{peername => Peername}).

apps/emqx/src/emqx_logger_textfmt.erl

@@ -69,7 +69,9 @@ enrich_report(ReportRaw, Meta) ->
     ClientId = maps:get(clientid, Meta, undefined),
     Peer = maps:get(peername, Meta, undefined),
     Msg = maps:get(msg, ReportRaw, undefined),
-    Tag = maps:get(tag, ReportRaw, undefined),
+    %% TODO: move all tags to Meta so we can filter traces
+    %% based on tags (currently not supported)
+    Tag = maps:get(tag, ReportRaw, maps:get(tag, Meta, undefined)),
     %% turn it into a list so that the order of the fields is determined
     lists:foldl(
         fun

apps/emqx_conf/src/emqx_conf_schema.erl

@@ -78,6 +78,7 @@
 -define(DEFAULT_MAX_PORTS, 1024 * 1024).
 
 -define(LOG_THROTTLING_MSGS, [
+    authentication_failure,
     authorization_permission_denied,
     cannot_publish_to_topic_due_to_not_authorized,
     cannot_publish_to_topic_due_to_quota_exceeded,