refactor(authz): improve logging

Move authz result logging to common place.

Prior to this change, the final result is not logged when
fallback to the default authorization.no_match config value.

Aso, if the result is provided by a hook callback,
it's also not logged.

After this change, only the final result is logged.
The authz chain resutls can be traced (or logged at debug level).

apps/emqx/include/emqx_access_control.hrl

@@ -24,9 +24,13 @@
 -define(DEFAULT_ACTION_QOS, 0).
 -define(DEFAULT_ACTION_RETAIN, false).
 
+-define(AUTHZ_SUBSCRIBE_MATCH_MAP(QOS), #{action_type := subscribe, qos := QOS}).
 -define(AUTHZ_SUBSCRIBE(QOS), #{action_type => subscribe, qos => QOS}).
 -define(AUTHZ_SUBSCRIBE, ?AUTHZ_SUBSCRIBE(?DEFAULT_ACTION_QOS)).
 
+-define(AUTHZ_PUBLISH_MATCH_MAP(QOS, RETAIN), #{
+    action_type := publish, qos := QOS, retain := RETAIN
+}).
 -define(AUTHZ_PUBLISH(QOS, RETAIN), #{action_type => publish, qos => QOS, retain => RETAIN}).
 -define(AUTHZ_PUBLISH(QOS), ?AUTHZ_PUBLISH(QOS, ?DEFAULT_ACTION_RETAIN)).
 -define(AUTHZ_PUBLISH, ?AUTHZ_PUBLISH(?DEFAULT_ACTION_QOS)).

apps/emqx/src/emqx_access_control.erl

@@ -22,7 +22,8 @@
 
 -export([
     authenticate/1,
-    authorize/3
+    authorize/3,
+    format_action/1
 ]).
 
 -ifdef(TEST).
@@ -152,6 +153,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, NoMatch),
             emqx_hooks:run(
                 'client.check_authz_complete',
                 [ClientInfo, Action, Topic, Result, From]
@@ -170,6 +172,42 @@ do_authorize(ClientInfo, Action, Topic) ->
             deny
     end.
 
+log_result(#{username := Username}, 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 -> ?SLOG(warning, (LogMeta())#{msg => "authorization_permission_denied"})
+    end.
+
+%% @private Format authorization rules source.
+format_from(default) ->
+    "'authorization.no_match' config";
+format_from(unknown) ->
+    "'client.authorize' hook callback";
+format_from(Type) ->
+    Type.
+
+%% @doc Format enriched action info for logging.
+format_action(?AUTHZ_SUBSCRIBE_MATCH_MAP(QoS)) ->
+    "SUBSCRIBE(" ++ format_qos(QoS) ++ ")";
+format_action(?AUTHZ_PUBLISH_MATCH_MAP(QoS, Retain)) ->
+    "PUBLISH(" ++ format_qos(QoS) ++ "," ++ format_retain_flag(Retain) ++ ")".
+
+format_qos(QoS) ->
+    "Q" ++ integer_to_list(QoS).
+
+format_retain_flag(true) ->
+    "R1";
+format_retain_flag(false) ->
+    "R0".
+
 -compile({inline, [run_hooks/3]}).
 run_hooks(Name, Args, Acc) ->
     ok = emqx_metrics:inc(Name),

apps/emqx_auth/src/emqx_authz/emqx_authz.erl

@@ -408,8 +408,7 @@ init_metrics(Source) ->
     {stop, #{result => deny, from => ?MODULE}}.
 authorize_deny(
     #{
-        username := Username,
-        peerhost := IpAddress
+        username := Username
     } = _Client,
     _PubSub,
     Topic,
@@ -419,13 +418,15 @@ authorize_deny(
     ?SLOG(warning, #{
         msg => "authorization_not_initialized",
         username => Username,
-        ipaddr => IpAddress,
         topic => Topic,
         source => ?MODULE
     }),
     {stop, #{result => deny, from => ?MODULE}}.
 
-%% @doc Check AuthZ
+%% @doc Check AuthZ.
+%% DefaultResult is always ignored in this callback because the final decision
+%% is to be made by `emqx_access_control' module after all authorization
+%% sources are exhausted.
 -spec authorize(
     emqx_types:clientinfo(),
     emqx_types:pubsub(),
@@ -434,77 +435,36 @@ authorize_deny(
     sources()
 ) ->
     authz_result().
-authorize(
-    #{
-        username := Username,
-        peerhost := IpAddress
-    } = Client,
-    PubSub,
-    Topic,
-    DefaultResult,
-    Sources
-) ->
+authorize(Client, PubSub, Topic, _DefaultResult, Sources) ->
     case maps:get(is_superuser, Client, false) of
         true ->
-            log_allowed(#{
-                username => Username,
-                ipaddr => IpAddress,
-                topic => Topic,
-                is_superuser => true
-            }),
             emqx_metrics:inc(?METRIC_SUPERUSER),
             {stop, #{result => allow, from => superuser}};
         false ->
-            authorize_non_superuser(Client, PubSub, Topic, DefaultResult, Sources)
+            authorize_non_superuser(Client, PubSub, Topic, Sources)
     end.
 
-authorize_non_superuser(
-    #{
-        username := Username,
-        peerhost := IpAddress
-    } = Client,
-    PubSub,
-    Topic,
-    _DefaultResult,
-    Sources
-) ->
+authorize_non_superuser(Client, PubSub, Topic, Sources) ->
     case do_authorize(Client, PubSub, Topic, sources_with_defaults(Sources)) of
         {{matched, allow}, AuthzSource} ->
-            log_allowed(#{
-                username => Username,
-                ipaddr => IpAddress,
-                topic => Topic,
-                source => AuthzSource
-            }),
             emqx_metrics_worker:inc(authz_metrics, AuthzSource, allow),
             emqx_metrics:inc(?METRIC_ALLOW),
-            {stop, #{result => allow, from => AuthzSource}};
+            {stop, #{result => allow, from => source_for_logging(AuthzSource, Client)}};
         {{matched, deny}, AuthzSource} ->
-            ?SLOG(warning, #{
-                msg => "authorization_permission_denied",
-                username => Username,
-                ipaddr => IpAddress,
-                topic => Topic,
-                source => AuthzSource
-            }),
             emqx_metrics_worker:inc(authz_metrics, AuthzSource, deny),
             emqx_metrics:inc(?METRIC_DENY),
-            {stop, #{result => deny, from => AuthzSource}};
+            {stop, #{result => deny, from => source_for_logging(AuthzSource, Client)}};
         nomatch ->
             ?tp(authz_non_superuser, #{result => nomatch}),
-            ?SLOG(info, #{
-                msg => "authorization_failed_nomatch",
-                username => Username,
-                ipaddr => IpAddress,
-                topic => Topic,
-                reason => "no-match rule"
-            }),
             emqx_metrics:inc(?METRIC_NOMATCH),
+            %% return ignore here because there might be other hook callbacks
             ignore
     end.
 
-log_allowed(Meta) ->
-    ?SLOG(info, Meta#{msg => "authorization_permission_allowed"}).
+source_for_logging(client_info, #{acl := Acl}) ->
+    maps:get(source_for_logging, Acl, client_info);
+source_for_logging(Type, _) ->
+    Type.
 
 do_authorize(_Client, _PubSub, _Topic, []) ->
     nomatch;
@@ -512,8 +472,7 @@ do_authorize(Client, PubSub, Topic, [#{enable := false} | Rest]) ->
     do_authorize(Client, PubSub, Topic, Rest);
 do_authorize(
     #{
-        username := Username,
-        peerhost := IpAddress
+        username := Username
     } = Client,
     PubSub,
     Topic,
@@ -527,9 +486,8 @@ do_authorize(
             ?TRACE("AUTHZ", "authorization_module_nomatch", #{
                 module => Module,
                 username => Username,
-                ipaddr => IpAddress,
                 topic => Topic,
-                pub_sub => PubSub
+                action => emqx_access_control:format_action(PubSub)
             }),
             do_authorize(Client, PubSub, Topic, Tail);
         %% {matched, allow | deny | ignore}
@@ -537,18 +495,16 @@ do_authorize(
             ?TRACE("AUTHZ", "authorization_module_match_ignore", #{
                 module => Module,
                 username => Username,
-                ipaddr => IpAddress,
                 topic => Topic,
-                pub_sub => PubSub
+                action => emqx_access_control:format_action(PubSub)
             }),
             do_authorize(Client, PubSub, Topic, Tail);
         ignore ->
             ?TRACE("AUTHZ", "authorization_module_ignore", #{
                 module => Module,
                 username => Username,
-                ipaddr => IpAddress,
                 topic => Topic,
-                pub_sub => PubSub
+                action => emqx_access_control:format_action(PubSub)
             }),
             do_authorize(Client, PubSub, Topic, Tail);
         %% {matched, allow | deny}

apps/emqx_auth/src/emqx_authz/emqx_authz_rule.erl

@@ -106,9 +106,15 @@ compile({Permission, Who, Action, TopicFilters}) when
      || Topic <- TopicFilters
     ]};
 compile({Permission, _Who, _Action, _TopicFilter}) when not ?IS_PERMISSION(Permission) ->
-    throw({invalid_authorization_permission, Permission});
+    throw(#{
+        reason => invalid_authorization_permission,
+        value => Permission
+    });
 compile(BadRule) ->
-    throw({invalid_authorization_rule, BadRule}).
+    throw(#{
+        reason => invalid_authorization_rule,
+        value => BadRule
+    }).
 
 compile_action(Action) ->
     compile_action(emqx_authz:feature_available(rich_actions), Action).
@@ -133,7 +139,10 @@ compile_action(true = _RichActionsOn, {Action, Opts}) when
         retain => retain_from_opts(Opts)
     };
 compile_action(_RichActionsOn, Action) ->
-    throw({invalid_authorization_action, Action}).
+    throw(#{
+        reason => invalid_authorization_action,
+        value => Action
+    }).
 
 qos_from_opts(Opts) ->
     try
@@ -152,20 +161,29 @@ qos_from_opts(Opts) ->
                 )
         end
     catch
-        bad_qos ->
-            throw({invalid_authorization_qos, Opts})
+        {bad_qos, QoS} ->
+            throw(#{
+                reason => invalid_authorization_qos,
+                qos => QoS
+            })
     end.
 
 validate_qos(QoS) when is_integer(QoS), QoS >= 0, QoS =< 2 ->
     QoS;
-validate_qos(_) ->
-    throw(bad_qos).
+validate_qos(QoS) ->
+    throw({bad_qos, QoS}).
 
 retain_from_opts(Opts) ->
     case proplists:get_value(retain, Opts, ?DEFAULT_RULE_RETAIN) of
-        all -> all;
-        Retain when is_boolean(Retain) -> Retain;
-        _ -> throw({invalid_authorization_retain, Opts})
+        all ->
+            all;
+        Retain when is_boolean(Retain) ->
+            Retain;
+        Value ->
+            throw(#{
+                reason => invalid_authorization_retain,
+                value => Value
+            })
     end.
 
 compile_who(all) ->
@@ -193,7 +211,10 @@ compile_who({'and', L}) when is_list(L) ->
 compile_who({'or', L}) when is_list(L) ->
     {'or', [compile_who(Who) || Who <- L]};
 compile_who(Who) ->
-    throw({invalid_who, Who}).
+    throw(#{
+        reason => invalid_client_match_condition,
+        identifier => Who
+    }).
 
 compile_topic("eq " ++ Topic) ->
     {eq, emqx_topic:words(bin(Topic))};
@@ -254,9 +275,17 @@ match_action(#{action_type := subscribe, qos := QoS}, #{action_type := subscribe
     match_qos(QoS, QoSCond);
 match_action(#{action_type := subscribe, qos := QoS}, #{action_type := all, qos := QoSCond}) ->
     match_qos(QoS, QoSCond);
-match_action(_, _) ->
+match_action(_, PubSubCond) ->
+    true = is_pubsub_cond(PubSubCond),
     false.
 
+is_pubsub_cond(publish) ->
+    true;
+is_pubsub_cond(subscribe) ->
+    true;
+is_pubsub_cond(#{action_type := A}) ->
+    is_pubsub_cond(A).
+
 match_pubsub(publish, publish) -> true;
 match_pubsub(subscribe, subscribe) -> true;
 match_pubsub(_, all) -> true;

apps/emqx_auth/src/emqx_authz/emqx_authz_rule_raw.erl

@@ -37,7 +37,7 @@
         emqx_authz_rule:action_condition(),
         emqx_authz_rule:topic_condition()
     }}
-    | {error, term()}.
+    | {error, map()}.
 parse_rule(
     #{
         <<"permission">> := PermissionRaw,

apps/emqx_auth/test/emqx_authz/emqx_authz_SUITE.erl

@@ -178,11 +178,13 @@ t_bad_file_source(_) ->
     BadContent = ?SOURCE_FILE(<<"{allow,{username,\"bar\"}, publish, [\"test\"]}">>),
     BadContentErr = {bad_acl_file_content, {1, erl_parse, ["syntax error before: ", []]}},
     BadRule = ?SOURCE_FILE(<<"{allow,{username,\"bar\"},publish}.">>),
-    BadRuleErr = {invalid_authorization_rule, {allow, {username, "bar"}, publish}},
+    BadRuleErr = #{
+        reason => invalid_authorization_rule, value => {allow, {username, "bar"}, publish}
+    },
     BadPermission = ?SOURCE_FILE(<<"{not_allow,{username,\"bar\"},publish,[\"test\"]}.">>),
-    BadPermissionErr = {invalid_authorization_permission, not_allow},
+    BadPermissionErr = #{reason => invalid_authorization_permission, value => not_allow},
     BadAction = ?SOURCE_FILE(<<"{allow,{username,\"bar\"},pubsub,[\"test\"]}.">>),
-    BadActionErr = {invalid_authorization_action, pubsub},
+    BadActionErr = #{reason => invalid_authorization_action, value => pubsub},
     lists:foreach(
         fun({Source, Error}) ->
             File = emqx_authz_file:acl_conf_file(),

apps/emqx_auth/test/emqx_authz/emqx_authz_file_SUITE.erl

@@ -100,7 +100,7 @@ t_rich_actions(_Config) ->
 t_no_rich_actions(_Config) ->
     _ = emqx_authz:set_feature_available(rich_actions, false),
     ?assertMatch(
-        {error, {pre_config_update, emqx_authz, {invalid_authorization_action, _}}},
+        {error, {pre_config_update, emqx_authz, #{reason := invalid_authorization_action}}},
         emqx_authz:update(?CMD_REPLACE, [
             ?RAW_SOURCE#{
                 <<"rules">> =>

apps/emqx_auth/test/emqx_authz/emqx_authz_rule_SUITE.erl

@@ -176,7 +176,7 @@ t_compile_ce(_Config) ->
     _ = emqx_authz:set_feature_available(rich_actions, false),
 
     ?assertThrow(
-        {invalid_authorization_action, _},
+        #{reason := invalid_authorization_action},
         emqx_authz_rule:compile(
             {allow, {username, "test"}, {all, [{qos, 2}, {retain, true}]}, ["topic/test"]}
         )
@@ -676,34 +676,34 @@ t_match(_) ->
 
 t_invalid_rule(_) ->
     ?assertThrow(
-        {invalid_authorization_permission, _},
+        #{reason := invalid_authorization_permission},
         emqx_authz_rule:compile({allawww, all, all, ["topic/test"]})
     ),
 
     ?assertThrow(
-        {invalid_authorization_rule, _},
+        #{reason := invalid_authorization_rule},
         emqx_authz_rule:compile(ooops)
     ),
 
     ?assertThrow(
-        {invalid_authorization_qos, _},
+        #{reason := invalid_authorization_qos},
         emqx_authz_rule:compile({allow, {username, "test"}, {publish, [{qos, 3}]}, ["topic/test"]})
     ),
 
     ?assertThrow(
-        {invalid_authorization_retain, _},
+        #{reason := invalid_authorization_retain},
         emqx_authz_rule:compile(
             {allow, {username, "test"}, {publish, [{retain, 'FALSE'}]}, ["topic/test"]}
         )
     ),
 
     ?assertThrow(
-        {invalid_authorization_action, _},
+        #{reason := invalid_authorization_action},
         emqx_authz_rule:compile({allow, all, unsubscribe, ["topic/test"]})
     ),
 
     ?assertThrow(
-        {invalid_who, _},
+        #{reason := invalid_client_match_condition},
         emqx_authz_rule:compile({allow, who, all, ["topic/test"]})
     ).