From 1a236db91b17effd485c2af60cb119cecac5712b Mon Sep 17 00:00:00 2001 From: Ilya Averyanov Date: Wed, 20 Jul 2022 19:40:19 +0300 Subject: [PATCH] chore(log): add authentication tracing --- CHANGES-5.0.md | 3 +- apps/emqx/include/emqx_authentication.hrl | 13 ++++ apps/emqx/include/logger.hrl | 18 +++-- apps/emqx/src/emqx_authentication.erl | 31 ++++++--- apps/emqx/src/emqx_trace/emqx_trace.erl | 15 ++-- .../src/emqx_trace/emqx_trace_formatter.erl | 53 ++++++++------- apps/emqx_authn/include/emqx_authn.hrl | 4 +- apps/emqx_authn/src/emqx_authn_utils.erl | 16 ++++- .../emqx_enhanced_authn_scram_mnesia.erl | 10 ++- .../src/simple_authn/emqx_authn_http.erl | 68 ++++++++++--------- .../src/simple_authn/emqx_authn_jwt.erl | 34 ++++++---- .../src/simple_authn/emqx_authn_mnesia.erl | 8 ++- .../src/simple_authn/emqx_authn_mongodb.erl | 7 +- .../src/simple_authn/emqx_authn_mysql.erl | 3 +- .../src/simple_authn/emqx_authn_pgsql.erl | 3 +- .../src/simple_authn/emqx_authn_redis.erl | 8 +-- 16 files changed, 182 insertions(+), 112 deletions(-) diff --git a/CHANGES-5.0.md b/CHANGES-5.0.md index e278c9502..6e22050fe 100644 --- a/CHANGES-5.0.md +++ b/CHANGES-5.0.md @@ -23,7 +23,8 @@ * Improve the dashboard listener startup log, the listener name is no longer spliced with port information, and the colon(:) is no longer displayed when IP is not specified. [#8480](https://github.com/emqx/emqx/pull/8480) * Remove `/configs/listeners` API, use `/listeners/` instead. [#8485](https://github.com/emqx/emqx/pull/8485) -* Optimize performance of builtin database operations in processes with long message queue [8439](https://github.com/emqx/emqx/pull/8439) +* Optimize performance of builtin database operations in processes with long message queue [#8439](https://github.com/emqx/emqx/pull/8439) +* Improve authentication tracing. [#8554](https://github.com/emqx/emqx/pull/8554) # 5.0.3 diff --git a/apps/emqx/include/emqx_authentication.hrl b/apps/emqx/include/emqx_authentication.hrl index dc501d1d8..6187b136c 100644 --- a/apps/emqx/include/emqx_authentication.hrl +++ b/apps/emqx/include/emqx_authentication.hrl @@ -17,6 +17,19 @@ -ifndef(EMQX_AUTHENTICATION_HRL). -define(EMQX_AUTHENTICATION_HRL, true). +-include_lib("emqx/include/logger.hrl"). + +-define(AUTHN_TRACE_TAG, "AUTHN"). + +-define(TRACE_AUTHN_PROVIDER(Msg), ?TRACE_AUTHN_PROVIDER(Msg, #{})). +-define(TRACE_AUTHN_PROVIDER(Msg, Meta), ?TRACE_AUTHN_PROVIDER(debug, Msg, Meta)). +-define(TRACE_AUTHN_PROVIDER(Level, Msg, Meta), + ?TRACE_AUTHN(Level, Msg, (Meta)#{provider => ?MODULE}) +). + +-define(TRACE_AUTHN(Msg, Meta), ?TRACE_AUTHN(debug, Msg, Meta)). +-define(TRACE_AUTHN(Level, Msg, Meta), ?TRACE(Level, ?AUTHN_TRACE_TAG, Msg, Meta)). + %% config root name all auth providers have to agree on. -define(EMQX_AUTHENTICATION_CONFIG_ROOT_NAME, "authentication"). -define(EMQX_AUTHENTICATION_CONFIG_ROOT_NAME_ATOM, authentication). diff --git a/apps/emqx/include/logger.hrl b/apps/emqx/include/logger.hrl index 05e5359b5..d321330a8 100644 --- a/apps/emqx/include/logger.hrl +++ b/apps/emqx/include/logger.hrl @@ -42,17 +42,21 @@ -define(TRACE_FILTER, emqx_trace_filter). +-define(TRACE(Tag, Msg, Meta), ?TRACE(debug, Tag, Msg, Meta)). + %% Only evaluate when necessary -%% Always debug the trace events. --define(TRACE(Tag, Msg, Meta), begin - case persistent_term:get(?TRACE_FILTER, undefined) of - undefined -> ok; +-define(TRACE(Level, Tag, Msg, Meta), begin + case persistent_term:get(?TRACE_FILTER, []) of [] -> ok; - List -> emqx_trace:log(List, Msg, Meta#{trace_tag => Tag}) + %% We can't bind filter list to a variablebecause we pollute the calling scope with it. + %% We also don't want to wrap the macro body in a fun + %% beacause 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, ?SLOG( - debug, - (emqx_trace_formatter:format_meta(Meta))#{msg => Msg, tag => Tag}, + Level, + (emqx_trace_formatter:format_meta_map(Meta))#{msg => Msg, tag => Tag}, #{is_trace => false} ) end). diff --git a/apps/emqx/src/emqx_authentication.erl b/apps/emqx/src/emqx_authentication.erl index e7e89465d..964a97dfb 100644 --- a/apps/emqx/src/emqx_authentication.erl +++ b/apps/emqx/src/emqx_authentication.erl @@ -101,6 +101,14 @@ -define(CHAINS_TAB, emqx_authn_chains). +-define(TRACE_RESULT(Label, Result, Reason), begin + ?TRACE_AUTHN(Label, #{ + result => (Result), + reason => (Reason) + }), + Result +end). + -type chain_name() :: atom(). -type authenticator_id() :: binary(). -type position() :: front | rear | {before, authenticator_id()} | {'after', authenticator_id()}. @@ -216,14 +224,14 @@ when authenticate(#{enable_authn := false}, _AuthResult) -> inc_authenticate_metric('authentication.success.anonymous'), - ignore; + ?TRACE_RESULT("authentication_result", ignore, enable_authn_false); authenticate(#{listener := Listener, protocol := Protocol} = Credential, _AuthResult) -> case get_authenticators(Listener, global_chain(Protocol)) of {ok, ChainName, Authenticators} -> case get_enabled(Authenticators) of [] -> inc_authenticate_metric('authentication.success.anonymous'), - ignore; + ?TRACE_RESULT("authentication_result", ignore, empty_chain); NAuthenticators -> Result = do_authenticate(ChainName, NAuthenticators, Credential), @@ -235,11 +243,11 @@ authenticate(#{listener := Listener, protocol := Protocol} = Credential, _AuthRe _ -> ok end, - Result + ?TRACE_RESULT("authentication_result", Result, chain_result) end; none -> inc_authenticate_metric('authentication.success.anonymous'), - ignore + ?TRACE_RESULT("authentication_result", ignore, no_chain) end. get_authenticators(Listener, Global) -> @@ -626,11 +634,11 @@ handle_create_authenticator(Chain, Config, Providers) -> do_authenticate(_ChainName, [], _) -> {stop, {error, not_authorized}}; do_authenticate( - ChainName, [#authenticator{id = ID, provider = Provider, state = State} | More], Credential + ChainName, [#authenticator{id = ID} = Authenticator | More], Credential ) -> MetricsID = metrics_id(ChainName, ID), emqx_metrics_worker:inc(authn_metrics, MetricsID, total), - try Provider:authenticate(Credential, State) of + try authenticate_with_provider(Authenticator, Credential) of ignore -> ok = emqx_metrics_worker:inc(authn_metrics, MetricsID, nomatch), do_authenticate(ChainName, More, Credential); @@ -651,8 +659,7 @@ do_authenticate( {stop, Result} catch Class:Reason:Stacktrace -> - ?SLOG(warning, #{ - msg => "unexpected_error_in_authentication", + ?TRACE_AUTHN(warning, "authenticator_error", #{ exception => Class, reason => Reason, stacktrace => Stacktrace, @@ -662,6 +669,14 @@ do_authenticate( do_authenticate(ChainName, More, Credential) end. +authenticate_with_provider(#authenticator{id = ID, provider = Provider, state = State}, Credential) -> + AuthnResult = Provider:authenticate(Credential, State), + ?TRACE_AUTHN("authenticator_result", #{ + authenticator => ID, + result => AuthnResult + }), + AuthnResult. + reply(Reply, State) -> {reply, Reply, State}. diff --git a/apps/emqx/src/emqx_trace/emqx_trace.erl b/apps/emqx/src/emqx_trace/emqx_trace.erl index 162ed4770..e6ee4260f 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace.erl @@ -92,15 +92,16 @@ unsubscribe(<<"$SYS/", _/binary>>, _SubOpts) -> unsubscribe(Topic, SubOpts) -> ?TRACE("UNSUBSCRIBE", "unsubscribe", #{topic => Topic, sub_opts => SubOpts}). -log(List, Msg, Meta0) -> - Meta = - case logger:get_process_metadata() of - undefined -> Meta0; - ProcMeta -> maps:merge(ProcMeta, Meta0) - end, - Log = #{level => debug, meta => Meta, msg => Msg}, +log(List, Msg, Meta) -> + Log = #{level => debug, meta => enrich_meta(Meta), msg => Msg}, log_filter(List, Log). +enrich_meta(Meta) -> + case logger:get_process_metadata() of + undefined -> Meta; + ProcMeta -> maps:merge(ProcMeta, Meta) + end. + log_filter([], _Log) -> ok; log_filter([{Id, FilterFun, Filter, Name} | Rest], Log0) -> diff --git a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl index 33c718b72..de909ffda 100644 --- a/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl +++ b/apps/emqx/src/emqx_trace/emqx_trace_formatter.erl @@ -16,7 +16,7 @@ -module(emqx_trace_formatter). -export([format/2]). --export([format_meta/1]). +-export([format_meta_map/1]). %%%----------------------------------------------------------------- %%% API @@ -31,32 +31,39 @@ 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"]; + [Time, " [", Tag, "] ", ClientId, "@", Peername, " msg: ", Msg, ", ", MetaBin, "\n"]; format(Event, Config) -> emqx_logger_textfmt:format(Event, Config). -format_meta(Meta) -> +format_meta_map(Meta) -> Encode = emqx_trace_handler:payload_encode(), - do_format_meta(Meta, Encode). + format_meta_map(Meta, Encode). -format_meta(Meta0, Encode) -> - Meta1 = #{packet := Packet0, payload := Payload0} = do_format_meta(Meta0, Encode), - Packet = enrich(", packet: ", Packet0), - Payload = enrich(", payload: ", Payload0), - Meta2 = maps:without([msg, clientid, peername, packet, payload, trace_tag], Meta1), - case Meta2 =:= #{} of - true -> [Packet, Payload]; - false -> [Packet, ", ", map_to_iolist(Meta2), Payload] +format_meta_map(Meta, Encode) -> + format_meta_map(Meta, Encode, [{packet, fun format_packet/2}, {payload, fun format_payload/2}]). + +format_meta_map(Meta, _Encode, []) -> + Meta; +format_meta_map(Meta, Encode, [{Name, FormatFun} | Rest]) -> + case Meta of + #{Name := Value} -> + NewMeta = Meta#{Name => FormatFun(Value, Encode)}, + format_meta_map(NewMeta, Encode, Rest); + #{} -> + format_meta_map(Meta, Encode, Rest) end. -enrich(_, "") -> ""; -enrich(Key, IoData) -> [Key, IoData]. +format_meta(Meta0, Encode) -> + Meta1 = maps:without([msg, clientid, peername, trace_tag], Meta0), + Meta2 = format_meta_map(Meta1, Encode), + kvs_to_iolist(lists:sort(fun compare_meta_kvs/2, maps:to_list(Meta2))). -do_format_meta(Meta, Encode) -> - Meta#{ - packet => format_packet(maps:get(packet, Meta, undefined), Encode), - payload => format_payload(maps:get(payload, Meta, undefined), Encode) - }. +%% packet always goes first; payload always goes last +compare_meta_kvs(KV1, KV2) -> weight(KV1) =< weight(KV2). + +weight({packet, _}) -> {0, packet}; +weight({payload, _}) -> {2, payload}; +weight({K, _}) -> {1, K}. format_packet(undefined, _) -> ""; format_packet(Packet, Encode) -> emqx_packet:format(Packet, Encode). @@ -69,14 +76,14 @@ format_payload(_, hidden) -> "******". to_iolist(Atom) when is_atom(Atom) -> atom_to_list(Atom); to_iolist(Int) when is_integer(Int) -> integer_to_list(Int); to_iolist(Float) when is_float(Float) -> float_to_list(Float, [{decimals, 2}]); -to_iolist(SubMap) when is_map(SubMap) -> ["[", map_to_iolist(SubMap), "]"]; +to_iolist(SubMap) when is_map(SubMap) -> ["[", kvs_to_iolist(maps:to_list(SubMap)), "]"]; to_iolist(Char) -> emqx_logger_textfmt:try_format_unicode(Char). -map_to_iolist(Map) -> +kvs_to_iolist(KVs) -> lists:join( - ",", + ", ", lists:map( fun({K, V}) -> [to_iolist(K), ": ", to_iolist(V)] end, - maps:to_list(Map) + KVs ) ). diff --git a/apps/emqx_authn/include/emqx_authn.hrl b/apps/emqx_authn/include/emqx_authn.hrl index f07904b6b..d59eea1af 100644 --- a/apps/emqx_authn/include/emqx_authn.hrl +++ b/apps/emqx_authn/include/emqx_authn.hrl @@ -36,6 +36,6 @@ -type authenticator_id() :: binary(). --endif. - -define(RESOURCE_GROUP, <<"emqx_authn">>). + +-endif. diff --git a/apps/emqx_authn/src/emqx_authn_utils.erl b/apps/emqx_authn/src/emqx_authn_utils.erl index 8d3d45b1b..17ad8a28b 100644 --- a/apps/emqx_authn/src/emqx_authn_utils.erl +++ b/apps/emqx_authn/src/emqx_authn_utils.erl @@ -33,7 +33,8 @@ bin/1, ensure_apps_started/1, cleanup_resources/0, - make_resource_id/1 + make_resource_id/1, + without_password/1 ]). -define(AUTHN_PLACEHOLDERS, [ @@ -199,10 +200,23 @@ make_resource_id(Name) -> NameBin = bin(Name), emqx_resource:generate_id(NameBin). +without_password(Credential) -> + without_password(Credential, [password, <<"password">>]). + %%-------------------------------------------------------------------- %% Internal functions %%-------------------------------------------------------------------- +without_password(Credential, []) -> + Credential; +without_password(Credential, [Name | Rest]) -> + case maps:is_key(Name, Credential) of + true -> + without_password(Credential#{Name => <<"[password]">>}, Rest); + false -> + without_password(Credential, Rest) + end. + handle_var({var, Name}, undefined) -> error({cannot_get_variable, Name}); handle_var({var, <<"peerhost">>}, PeerHost) -> diff --git a/apps/emqx_authn/src/enhanced_authn/emqx_enhanced_authn_scram_mnesia.erl b/apps/emqx_authn/src/enhanced_authn/emqx_enhanced_authn_scram_mnesia.erl index 9688ef65a..bc26140a6 100644 --- a/apps/emqx_authn/src/enhanced_authn/emqx_enhanced_authn_scram_mnesia.erl +++ b/apps/emqx_authn/src/enhanced_authn/emqx_enhanced_authn_scram_mnesia.erl @@ -331,7 +331,10 @@ check_client_first_message(Bin, _Cache, #{iteration_count := IterationCount} = S {continue, ServerFirstMessage, Cache}; ignore -> ignore; - {error, _Reason} -> + {error, Reason} -> + ?TRACE_AUTHN_PROVIDER("check_client_first_message_error", #{ + reason => Reason + }), {error, not_authorized} end. @@ -344,7 +347,10 @@ check_client_final_message(Bin, #{is_superuser := IsSuperuser} = Cache, #{algori of {ok, ServerFinalMessage} -> {ok, #{is_superuser => IsSuperuser}, ServerFinalMessage}; - {error, _Reason} -> + {error, Reason} -> + ?TRACE_AUTHN_PROVIDER("check_client_final_message_error", #{ + reason => Reason + }), {error, not_authorized} end. diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_http.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_http.erl index 8dccb9ee3..db3eb3c2f 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_http.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_http.erl @@ -188,23 +188,22 @@ authenticate( } = State ) -> Request = generate_request(Credential, State), - case emqx_resource:query(ResourceId, {Method, Request, RequestTimeout}) of + Response = emqx_resource:query(ResourceId, {Method, Request, RequestTimeout}), + ?TRACE_AUTHN_PROVIDER("http_response", #{ + request => request_for_log(Credential, State), + response => response_for_log(Response), + resource => ResourceId + }), + case Response of {ok, 204, _Headers} -> {ok, #{is_superuser => false}}; {ok, 200, Headers, Body} -> handle_response(Headers, Body); {ok, _StatusCode, _Headers} = Response -> - log_response(ResourceId, Response), ignore; {ok, _StatusCode, _Headers, _Body} = Response -> - log_response(ResourceId, Response), ignore; - {error, Reason} -> - ?SLOG(error, #{ - msg => "http_server_query_failed", - resource => ResourceId, - reason => Reason - }), + {error, _Reason} -> ignore end. @@ -296,7 +295,8 @@ parse_config( cow_qs:parse_qs(to_bin(Query)) ), body_template => emqx_authn_utils:parse_deep(maps:get(body, Config, #{})), - request_timeout => RequestTimeout + request_timeout => RequestTimeout, + url => RawUrl }, {Config#{base_url => BaseUrl, pool_type => random}, State}. @@ -379,11 +379,6 @@ parse_body(<<"application/x-www-form-urlencoded", _/binary>>, Body) -> parse_body(ContentType, _) -> {error, {unsupported_content_type, ContentType}}. -may_append_body(Output, {ok, _, _, Body}) -> - Output#{body => Body}; -may_append_body(Output, {ok, _, _}) -> - Output. - uri_encode(T) -> emqx_http_lib:uri_encode(to_list(T)). @@ -391,26 +386,33 @@ encode_path(Path) -> Parts = string:split(Path, "/", all), lists:flatten(["/" ++ Part || Part <- lists:map(fun uri_encode/1, Parts)]). -log_response(ResourceId, Other) -> - Output = may_append_body(#{resource => ResourceId}, Other), - case erlang:element(2, Other) of - Code5xx when Code5xx >= 500 andalso Code5xx < 600 -> - ?SLOG(error, Output#{ - msg => "http_server_error", - code => Code5xx - }); - Code4xx when Code4xx >= 400 andalso Code4xx < 500 -> - ?SLOG(warning, Output#{ - msg => "refused_by_http_server", - code => Code4xx - }); - OtherCode -> - ?SLOG(error, Output#{ - msg => "undesired_response_code", - code => OtherCode - }) +request_for_log(Credential, #{url := Url} = State) -> + SafeCredential = emqx_authn_utils:without_password(Credential), + case generate_request(SafeCredential, State) of + {PathQuery, Headers} -> + #{ + method => post, + base_url => Url, + path_query => PathQuery, + headers => Headers + }; + {PathQuery, Headers, Body} -> + #{ + method => post, + base_url => Url, + path_query => PathQuery, + headers => Headers, + mody => Body + } end. +response_for_log({ok, StatusCode, Headers}) -> + #{status => StatusCode, headers => Headers}; +response_for_log({ok, StatusCode, Headers, Body}) -> + #{status => StatusCode, headers => Headers, body => Body}; +response_for_log({error, Error}) -> + #{error => Error}. + to_list(A) when is_atom(A) -> atom_to_list(A); to_list(B) when is_binary(B) -> diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_jwt.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_jwt.erl index 0017754a4..c6f2069ae 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_jwt.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_jwt.erl @@ -227,8 +227,7 @@ authenticate( ) -> case emqx_resource:query(ResourceId, get_jwks) of {error, Reason} -> - ?SLOG(error, #{ - msg => "get_jwks_failed", + ?TRACE_AUTHN_PROVIDER(error, "get_jwks_failed", #{ resource => ResourceId, reason => Reason }), @@ -350,10 +349,17 @@ verify(undefined, _, _, _) -> ignore; verify(JWT, JWKs, VerifyClaims, AclClaimName) -> case do_verify(JWT, JWKs, VerifyClaims) of - {ok, Extra} -> {ok, acl(Extra, AclClaimName)}; - {error, {missing_claim, _}} -> {error, bad_username_or_password}; - {error, invalid_signature} -> ignore; - {error, {claims, _}} -> {error, bad_username_or_password} + {ok, Extra} -> + {ok, acl(Extra, AclClaimName)}; + {error, {missing_claim, Claim}} -> + ?TRACE_AUTHN_PROVIDER("missing_jwt_claim", #{jwt => JWT, claim => Claim}), + {error, bad_username_or_password}; + {error, invalid_signature} -> + ?TRACE_AUTHN_PROVIDER("invalid_jwt_signature", #{jwks => JWKs, jwt => JWT}), + ignore; + {error, {claims, Claims}} -> + ?TRACE_AUTHN_PROVIDER("invalid_jwt_claims", #{jwt => JWT, claims => Claims}), + {error, bad_username_or_password} end. acl(Claims, AclClaimName) -> @@ -371,11 +377,11 @@ acl(Claims, AclClaimName) -> end, maps:merge(emqx_authn_utils:is_superuser(Claims), Acl). -do_verify(_JWS, [], _VerifyClaims) -> +do_verify(_JWT, [], _VerifyClaims) -> {error, invalid_signature}; -do_verify(JWS, [JWK | More], VerifyClaims) -> - try jose_jws:verify(JWK, JWS) of - {true, Payload, _JWS} -> +do_verify(JWT, [JWK | More], VerifyClaims) -> + try jose_jws:verify(JWK, JWT) of + {true, Payload, _JWT} -> Claims0 = emqx_json:decode(Payload, [return_maps]), Claims = try_convert_to_int(Claims0, [<<"exp">>, <<"iat">>, <<"nbf">>]), case verify_claims(Claims, VerifyClaims) of @@ -385,11 +391,11 @@ do_verify(JWS, [JWK | More], VerifyClaims) -> {error, Reason} end; {false, _, _} -> - do_verify(JWS, More, VerifyClaims) + do_verify(JWT, More, VerifyClaims) catch - _:_Reason -> - ?TRACE("JWT", "authn_jwt_invalid_signature", #{jwk => JWK, jws => JWS}), - {error, invalid_signature} + _:Reason -> + ?TRACE_AUTHN_PROVIDER("jwt_verify_error", #{jwk => JWK, jwt => JWT, reason => Reason}), + do_verify(JWT, More, VerifyClaims) end. verify_claims(Claims, VerifyClaims0) -> diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_mnesia.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_mnesia.erl index 81dc89c54..c3380b91f 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_mnesia.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_mnesia.erl @@ -17,6 +17,7 @@ -module(emqx_authn_mnesia). -include("emqx_authn.hrl"). +-include_lib("emqx/include/logger.hrl"). -include_lib("stdlib/include/ms_transform.hrl"). -include_lib("hocon/include/hoconsc.hrl"). @@ -158,6 +159,7 @@ authenticate( UserID = get_user_identity(Credential, Type), case mnesia:dirty_read(?TAB, {UserGroup, UserID}) of [] -> + ?TRACE_AUTHN_PROVIDER("user_not_found"), ignore; [#user_info{password_hash = PasswordHash, salt = Salt, is_superuser = IsSuperuser}] -> case @@ -165,8 +167,10 @@ authenticate( Algorithm, Salt, PasswordHash, Password ) of - true -> {ok, #{is_superuser => IsSuperuser}}; - false -> {error, bad_username_or_password} + true -> + {ok, #{is_superuser => IsSuperuser}}; + false -> + {error, bad_username_or_password} end end. diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_mongodb.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_mongodb.erl index a46d62c8c..f7249ae57 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_mongodb.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_mongodb.erl @@ -167,8 +167,7 @@ authenticate( undefined -> ignore; {error, Reason} -> - ?SLOG(error, #{ - msg => "mongodb_query_failed", + ?TRACE_AUTHN_PROVIDER(error, "mongodb_query_failed", #{ resource => ResourceId, collection => Collection, filter => Filter, @@ -180,11 +179,11 @@ authenticate( ok -> {ok, is_superuser(Doc, State)}; {error, {cannot_find_password_hash_field, PasswordHashField}} -> - ?SLOG(error, #{ - msg => "cannot_find_password_hash_field", + ?TRACE_AUTHN_PROVIDER(error, "cannot_find_password_hash_field", #{ resource => ResourceId, collection => Collection, filter => Filter, + document => Doc, password_hash_field => PasswordHashField }), ignore; diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_mysql.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_mysql.erl index d183748ff..e95302ad4 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_mysql.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_mysql.erl @@ -130,8 +130,7 @@ authenticate( {error, Reason} end; {error, Reason} -> - ?SLOG(error, #{ - msg => "mysql_query_failed", + ?TRACE_AUTHN_PROVIDER(error, "mysql_query_failed", #{ resource => ResourceId, tmpl_token => TmplToken, params => Params, diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_pgsql.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_pgsql.erl index 99f4fa43c..2962308ab 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_pgsql.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_pgsql.erl @@ -133,8 +133,7 @@ authenticate( {error, Reason} end; {error, Reason} -> - ?SLOG(error, #{ - msg => "postgresql_query_failed", + ?TRACE_AUTHN_PROVIDER(error, "postgresql_query_failed", #{ resource => ResourceId, params => Params, reason => Reason diff --git a/apps/emqx_authn/src/simple_authn/emqx_authn_redis.erl b/apps/emqx_authn/src/simple_authn/emqx_authn_redis.erl index d2003f26a..71cd292e6 100644 --- a/apps/emqx_authn/src/simple_authn/emqx_authn_redis.erl +++ b/apps/emqx_authn/src/simple_authn/emqx_authn_redis.erl @@ -128,13 +128,14 @@ authenticate(#{auth_method := _}, _) -> authenticate( #{password := Password} = Credential, #{ - cmd := {Command, KeyTemplate, Fields}, + cmd := {CommandName, KeyTemplate, Fields}, resource_id := ResourceId, password_hash_algorithm := Algorithm } ) -> NKey = emqx_authn_utils:render_str(KeyTemplate, Credential), - case emqx_resource:query(ResourceId, {cmd, [Command, NKey | Fields]}) of + Command = [CommandName, NKey | Fields], + case emqx_resource:query(ResourceId, {cmd, Command}) of {ok, []} -> ignore; {ok, Values} -> @@ -150,8 +151,7 @@ authenticate( {error, Reason} end; {error, Reason} -> - ?SLOG(error, #{ - msg => "redis_query_failed", + ?TRACE_AUTHN_PROVIDER(error, "redis_query_failed", #{ resource => ResourceId, cmd => Command, keys => NKey,