From 3314d9616dc636ee61dd3e33c976236aa8c6cda7 Mon Sep 17 00:00:00 2001 From: firest Date: Thu, 9 Feb 2023 14:08:42 +0800 Subject: [PATCH] fix(auth): add more detailed logs for auth/acl --- apps/emqx_auth_http/src/emqx_acl_http.erl | 6 ++++-- apps/emqx_auth_http/src/emqx_auth_http.erl | 5 +++-- apps/emqx_auth_jwt/src/emqx_auth_jwt.erl | 6 ++++++ apps/emqx_auth_ldap/src/emqx_acl_ldap.erl | 12 ++++++++++-- apps/emqx_auth_ldap/src/emqx_auth_ldap.erl | 3 +++ apps/emqx_auth_mnesia/src/emqx_acl_mnesia.erl | 7 +++++++ apps/emqx_auth_mnesia/src/emqx_auth_mnesia.erl | 3 +++ apps/emqx_auth_mongo/src/emqx_acl_mongo.erl | 12 ++++++++++-- apps/emqx_auth_mongo/src/emqx_auth_mongo.erl | 3 +++ apps/emqx_auth_mysql/src/emqx_acl_mysql.erl | 12 ++++++++++-- apps/emqx_auth_mysql/src/emqx_auth_mysql.erl | 3 +++ apps/emqx_auth_pgsql/src/emqx_acl_pgsql.erl | 15 +++++++++++---- apps/emqx_auth_pgsql/src/emqx_auth_pgsql.erl | 3 +++ apps/emqx_auth_redis/src/emqx_acl_redis.erl | 13 ++++++++++--- 14 files changed, 86 insertions(+), 17 deletions(-) diff --git a/apps/emqx_auth_http/src/emqx_acl_http.erl b/apps/emqx_auth_http/src/emqx_acl_http.erl index 3decdbf6d..e18527179 100644 --- a/apps/emqx_auth_http/src/emqx_acl_http.erl +++ b/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. - diff --git a/apps/emqx_auth_http/src/emqx_auth_http.erl b/apps/emqx_auth_http/src/emqx_auth_http.erl index aad08e7b6..c7710ae94 100644 --- a/apps/emqx_auth_http/src/emqx_auth_http.erl +++ b/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, diff --git a/apps/emqx_auth_jwt/src/emqx_auth_jwt.erl b/apps/emqx_auth_jwt/src/emqx_auth_jwt.erl index 63a59b5ec..dd3b2dbc9 100644 --- a/apps/emqx_auth_jwt/src/emqx_auth_jwt.erl +++ b/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. diff --git a/apps/emqx_auth_ldap/src/emqx_acl_ldap.erl b/apps/emqx_auth_ldap/src/emqx_acl_ldap.erl index d01eace21..8faeed913 100644 --- a/apps/emqx_auth_ldap/src/emqx_acl_ldap.erl +++ b/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, deny} -> {stop, deny} + {stop, allow} -> + ?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) -> diff --git a/apps/emqx_auth_ldap/src/emqx_auth_ldap.erl b/apps/emqx_auth_ldap/src/emqx_auth_ldap.erl index 33fa91618..d1d73784d 100644 --- a/apps/emqx_auth_ldap/src/emqx_auth_ldap.erl +++ b/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; diff --git a/apps/emqx_auth_mnesia/src/emqx_acl_mnesia.erl b/apps/emqx_auth_mnesia/src/emqx_acl_mnesia.erl index 576977ec1..928dcc608 100644 --- a/apps/emqx_auth_mnesia/src/emqx_acl_mnesia.erl +++ b/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 diff --git a/apps/emqx_auth_mnesia/src/emqx_auth_mnesia.erl b/apps/emqx_auth_mnesia/src/emqx_auth_mnesia.erl index 5a36be59b..35bea5fde 100644 --- a/apps/emqx_auth_mnesia/src/emqx_auth_mnesia.erl +++ b/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. diff --git a/apps/emqx_auth_mongo/src/emqx_acl_mongo.erl b/apps/emqx_auth_mongo/src/emqx_acl_mongo.erl index a7487dd07..2f069478b 100644 --- a/apps/emqx_auth_mongo/src/emqx_acl_mongo.erl +++ b/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}; - nomatch -> {stop, deny} + matched -> + ?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", diff --git a/apps/emqx_auth_mongo/src/emqx_auth_mongo.erl b/apps/emqx_auth_mongo/src/emqx_auth_mongo.erl index 1c8c18ce3..9ca272c65 100644 --- a/apps/emqx_auth_mongo/src/emqx_auth_mongo.erl +++ b/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}}; diff --git a/apps/emqx_auth_mysql/src/emqx_acl_mysql.erl b/apps/emqx_auth_mysql/src/emqx_acl_mysql.erl index 436c69d5f..a5b0f86b2 100644 --- a/apps/emqx_auth_mysql/src/emqx_acl_mysql.erl +++ b/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, deny} -> {stop, deny} + {stop, allow} -> + ?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) -> diff --git a/apps/emqx_auth_mysql/src/emqx_auth_mysql.erl b/apps/emqx_auth_mysql/src/emqx_auth_mysql.erl index ac35e6ce6..94045e1ad 100644 --- a/apps/emqx_auth_mysql/src/emqx_auth_mysql.erl +++ b/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}}; diff --git a/apps/emqx_auth_pgsql/src/emqx_acl_pgsql.erl b/apps/emqx_auth_pgsql/src/emqx_acl_pgsql.erl index ee385cd16..1afb93975 100644 --- a/apps/emqx_auth_pgsql/src/emqx_acl_pgsql.erl +++ b/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, deny} -> {stop, deny}; - nomatch -> ok + {matched, allow} -> + ?LOG_SENSITIVE(debug, + "[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. - diff --git a/apps/emqx_auth_pgsql/src/emqx_auth_pgsql.erl b/apps/emqx_auth_pgsql/src/emqx_auth_pgsql.erl index 6bdc53941..8f75c1279 100644 --- a/apps/emqx_auth_pgsql/src/emqx_auth_pgsql.erl +++ b/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}}; diff --git a/apps/emqx_auth_redis/src/emqx_acl_redis.erl b/apps/emqx_auth_redis/src/emqx_acl_redis.erl index 2fcdb9592..74a68905c 100644 --- a/apps/emqx_auth_redis/src/emqx_acl_redis.erl +++ b/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}; - nomatch -> {stop, deny} + allow -> + ?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". -