fix(auth): add more detailed logs for auth/acl

apps/emqx_auth_http/src/emqx_acl_http.erl

@@ -44,7 +44,10 @@ check_acl(ClientInfo, PubSub, Topic, _AclResult, #{acl := ACLParams = #{path :=
     Username = maps:get(username, ClientInfo1, undefined),
     case check_acl_request(ACLParams, ClientInfo1) of
         {ok, 200, <<"ignore">>} -> ok;
-        {ok, 200, _Body} -> {stop, allow};
+        {ok, 200, _Body} ->
+            ?LOG(debug, "Allow ~s to topic ~ts, username: ~ts",
+                 [PubSub, Topic, Username]),
+            {stop, allow};
         {ok, Code, _Body} ->
             ?LOG(warning, "Deny ~s to topic ~ts, username: ~ts, http response code: ~p",
                  [PubSub, Topic, Username, Code]),
@@ -74,4 +77,3 @@ check_acl_request(ACLParams =
 
 access(subscribe) -> 1;
 access(publish)   -> 2.
-

apps/emqx_auth_http/src/emqx_auth_http.erl

@@ -41,19 +41,20 @@ check(ClientInfo, AuthResult, #{auth  := AuthParms = #{path := Path},
         {ok, 200, <<"ignore">>} ->
             ok;
         {ok, 200, Body}  ->
+            ?LOG(debug, "Auth succeeded from path: ~ts, username: ~ts", [Path, Username]),
             IsSuperuser = is_superuser(SuperParams, ClientInfo),
             {stop, AuthResult#{is_superuser => IsSuperuser,
                                 auth_result => success,
                                 anonymous   => false,
                                 mountpoint  => mountpoint(Body, ClientInfo)}};
         {ok, Code, _Body} ->
-            ?LOG(warning, "Deny connection from path: ~s, username: ~ts, http "
+            ?LOG(warning, "Deny connection from path: ~ts, username: ~ts, http "
                           "response code: ~p",
                           [Path, Username, Code]),
             {stop, AuthResult#{auth_result => http_to_connack_error(Code),
                                anonymous   => false}};
         {error, Error} ->
-            ?LOG_SENSITIVE(warning, "Deny connection from path: ~s, username: ~ts, due to "
+            ?LOG_SENSITIVE(warning, "Deny connection from path: ~ts, username: ~ts, due to "
                                     "request http-server failed: ~0p", [Path, Username, Error]),
             %%FIXME later: server_unavailable is not right.
             {stop, AuthResult#{auth_result => server_unavailable,

apps/emqx_auth_jwt/src/emqx_auth_jwt.erl

@@ -51,8 +51,14 @@ check_auth(ClientInfo, AuthResult, #{from := From, checklists := Checklists}) ->
                 {error, not_token} ->
                     ok;
                 {error, Reason} ->
+                    ?LOG_SENSITIVE(debug,
+                                   "Auth from JWT failed, Client: ~p, Reason: ~p",
+                                   [ClientInfo, Reason]),
                     {stop, AuthResult#{auth_result => Reason, anonymous => false}};
                 {ok, Claims} ->
+                    ?LOG_SENSITIVE(debug,
+                                   "Auth from JWT succeeded, Client: ~p",
+                                   [ClientInfo]),
                     {stop, maps:merge(AuthResult, verify_claims(Checklists, Claims, ClientInfo))}
             end
     end.

apps/emqx_auth_ldap/src/emqx_acl_ldap.erl

@@ -29,8 +29,16 @@
 check_acl(ClientInfo, PubSub, Topic, NoMatchAction, State) ->
     case do_check_acl(ClientInfo, PubSub, Topic, NoMatchAction, State) of
         ok -> ok;
-        {stop, allow} -> {stop, allow};
+        {stop, allow} ->
-        {stop, deny} -> {stop, deny}
+            ?LOG_SENSITIVE(debug,
+                           "[LDAP] Allow Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
+            {stop, allow};
+        {stop, deny} ->
+            ?LOG_SENSITIVE(debug,
+                           "[LDAP] Deny Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
+            {stop, deny}
     end.
 
 do_check_acl(#{username := <<$$, _/binary>>}, _PubSub, _Topic, _NoMatchAction, _State) ->

apps/emqx_auth_ldap/src/emqx_auth_ldap.erl

@@ -58,6 +58,9 @@ check(ClientInfo = #{username := Username, password := Password}, AuthResult,
         end,
     case CheckResult of
         ok ->
+            ?LOG_SENSITIVE(debug,
+                           "[LDAP] Auth from ldap succeeded, Client: ~p",
+                           [ClientInfo]),
             {stop, AuthResult#{auth_result => success, anonymous => false}};
         {error, not_found} ->
             ok;

apps/emqx_auth_mnesia/src/emqx_acl_mnesia.erl

@@ -17,6 +17,7 @@
 -module(emqx_acl_mnesia).
 
 -include("emqx_auth_mnesia.hrl").
+-include_lib("emqx/include/logger.hrl").
 
 %% ACL Callbacks
 -export([ init/0
@@ -43,8 +44,14 @@ check_acl(ClientInfo = #{ clientid := Clientid }, PubSub, Topic, _NoMatchAction,
 
     case match(ClientInfo, PubSub, Topic, Acls) of
         allow ->
+            ?LOG_SENSITIVE(debug,
+                           "[Mnesia] Allow Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
             {stop, allow};
         deny ->
+            ?LOG_SENSITIVE(debug,
+                           "[Mnesia] Deny Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
             {stop, deny};
         _ ->
             ok

apps/emqx_auth_mnesia/src/emqx_auth_mnesia.erl

@@ -70,6 +70,9 @@ check(ClientInfo = #{ clientid := Clientid
                     ?LOG(info, "[Mnesia] Auth from mnesia failed: ~p", [Info]),
                     {stop, AuthResult#{anonymous => false, auth_result => password_error}};
                 _ ->
+                    ?LOG_SENSITIVE(debug,
+                                   "[Mnesia] Auth from mnesia succeeded, Client: ~p",
+                                   [ClientInfo]),
                     {stop, AuthResult#{anonymous => false, auth_result => success}}
             end
     end.

apps/emqx_auth_mongo/src/emqx_acl_mongo.erl

@@ -38,8 +38,16 @@ check_acl(ClientInfo, PubSub, Topic, _AclResult, Env = #{aclquery := AclQuery})
         [] -> ok;
         Rows ->
             try match(ClientInfo, Topic, topics(PubSub, Rows)) of
-                matched -> {stop, allow};
+                matched ->
-                nomatch -> {stop, deny}
+                    ?LOG_SENSITIVE(debug,
+                                   "[MongoDB] Allow Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, allow};
+                nomatch ->
+                    ?LOG_SENSITIVE(debug,
+                                   "[MongoDB] Deny Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, deny}
             catch
                 _Err:Reason->
                     ?LOG(error, "[MongoDB] Check mongo ~p ACL failed, got ACL config: ~p, error: :~p",

apps/emqx_auth_mongo/src/emqx_auth_mongo.erl

@@ -68,6 +68,9 @@ check(ClientInfo = #{password := Password}, AuthResult,
             case Result of
                 ok ->
                     ?tp(emqx_auth_mongo_superuser_check_authn_ok, #{}),
+                    ?LOG_SENSITIVE(debug,
+                                   "[MongoDB] Auth from mongo succeeded, Client: ~p",
+                                   [ClientInfo]),
                     {stop, AuthResult#{is_superuser => is_superuser(Pool, SuperQuery, ClientInfo),
                                        anonymous => false,
                                        auth_result => success}};

apps/emqx_auth_mysql/src/emqx_acl_mysql.erl

@@ -29,8 +29,16 @@
 check_acl(ClientInfo, PubSub, Topic, NoMatchAction, #{pool := Pool} = State) ->
     case do_check_acl(Pool, ClientInfo, PubSub, Topic, NoMatchAction, State) of
         ok -> ok;
-        {stop, allow} -> {stop, allow};
+        {stop, allow} ->
-        {stop, deny} -> {stop, deny}
+            ?LOG_SENSITIVE(debug,
+                           "[MySQL] Allow Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
+            {stop, allow};
+        {stop, deny} ->
+            ?LOG_SENSITIVE(debug,
+                           "[MySQL] Allow Topic: ~p, Action: ~p for Client: ~p",
+                           [Topic, PubSub, ClientInfo]),
+            {stop, deny}
     end.
 
 do_check_acl(_Pool, #{username := <<$$, _/binary>>}, _PubSub, _Topic, _NoMatchAction, _State) ->

apps/emqx_auth_mysql/src/emqx_auth_mysql.erl

@@ -46,6 +46,9 @@ check(ClientInfo = #{password := Password}, AuthResult,
                 end,
     case CheckPass of
         ok ->
+            ?LOG_SENSITIVE(debug,
+                           "[MySQL] Auth from mysql succeeded, Client: ~p",
+                           [ClientInfo]),
             {stop, AuthResult#{is_superuser => is_superuser(Pool, SuperQuery, ClientInfo),
                                 anonymous => false,
                                 auth_result => success}};

apps/emqx_auth_pgsql/src/emqx_acl_pgsql.erl

@@ -36,9 +36,17 @@ do_check_acl(Pool, ClientInfo, PubSub, Topic, _NoMatchAction, #{acl_query := {Ac
         {ok, _, Rows} ->
             Rules = filter(PubSub, compile(Rows)),
             case match(ClientInfo, Topic, Rules) of
-                {matched, allow} -> {stop, allow};
+                {matched, allow} ->
-                {matched, deny}  -> {stop, deny};
+                    ?LOG_SENSITIVE(debug,
-                nomatch          -> ok
+                                   "[Postgres] Allow Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, allow};
+                {matched, deny} ->
+                    ?LOG_SENSITIVE(debug,
+                                   "[Postgres] Deny Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, deny};
+                nomatch -> ok
             end;
         {error, Reason} ->
             ?LOG(error, "[Postgres] do_check_acl error: ~p~n", [Reason]),
@@ -105,4 +113,3 @@ empty(null) -> true;
 empty("")   -> true;
 empty(<<>>) -> true;
 empty(_)    -> false.
-

apps/emqx_auth_pgsql/src/emqx_auth_pgsql.erl

@@ -45,6 +45,9 @@ check(ClientInfo = #{password := Password}, AuthResult,
                 end,
     case CheckPass of
         ok ->
+            ?LOG_SENSITIVE(debug,
+                           "[Postgres] Auth from pgsql succeeded, Client: ~p",
+                           [ClientInfo]),
             {stop, AuthResult#{is_superuser => is_superuser(Pool, SuperQuery, ClientInfo),
                                 anonymous => false,
                                 auth_result => success}};

apps/emqx_auth_redis/src/emqx_acl_redis.erl

@@ -33,8 +33,16 @@ check_acl(ClientInfo, PubSub, Topic, _AclResult,
         {ok, []} -> ok;
         {ok, Rules} ->
             case match(ClientInfo, PubSub, Topic, Rules) of
-                allow   -> {stop, allow};
+                allow ->
-                nomatch -> {stop, deny}
+                    ?LOG_SENSITIVE(debug,
+                                   "[Redis] Allow Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, allow};
+                nomatch ->
+                    ?LOG_SENSITIVE(debug,
+                                   "[Redis] Deny Topic: ~p, Action: ~p for Client: ~p",
+                                   [Topic, PubSub, ClientInfo]),
+                    {stop, deny}
             end;
         {error, Reason} ->
             ?LOG(error, "[Redis] do_check_acl error: ~p", [Reason]),
@@ -71,4 +79,3 @@ feed_var(Str, Var, Val) ->
 b2i(Bin) -> list_to_integer(binary_to_list(Bin)).
 
 description() -> "Redis ACL Module".
-